diff --git a/.gitignore b/.gitignore index 243f2d008a0..a4a6ce22680 100644 --- a/.gitignore +++ b/.gitignore @@ -6,6 +6,9 @@ /cmd/util/util /cmd/bootstrap/bootstrap +# omit agent plans files +/docs/plans + # Test ouput of bootstrapping CLI cmd/bootstrap/bootstrap-example diff --git a/admin/commands/common/component_log_level_reset.go b/admin/commands/common/component_log_level_reset.go new file mode 100644 index 00000000000..4e20767b2d8 --- /dev/null +++ b/admin/commands/common/component_log_level_reset.go @@ -0,0 +1,79 @@ +package common + +import ( + "context" + "fmt" + "strings" + + "github.com/onflow/flow-go/admin" + "github.com/onflow/flow-go/admin/commands" + "github.com/onflow/flow-go/utils/logging" +) + +var _ commands.AdminCommand = (*ResetComponentLogLevelCommand)(nil) + +// ResetComponentLogLevelCommand removes runtime log level overrides for components matching +// the specified patterns, restoring them to static config or global default. +// +// Input is a JSON array of patterns. ["*"] resets all registered components. +// "*" may not be mixed with other patterns. +// +// Example input: +// +// ["hotstuff.voter", "hotstuff.*"] +// ["*"] +type ResetComponentLogLevelCommand struct { + registry *logging.LogRegistry +} + +// NewResetComponentLogLevelCommand constructs a ResetComponentLogLevelCommand. +func NewResetComponentLogLevelCommand(registry *logging.LogRegistry) *ResetComponentLogLevelCommand { + return &ResetComponentLogLevelCommand{registry: registry} +} + +// Validator validates that the input is a non-empty array of pattern strings. "*" must be +// the sole element if present. +// +// Returns [admin.InvalidAdminReqError] for invalid or malformed requests. +func (r *ResetComponentLogLevelCommand) Validator(req *admin.CommandRequest) error { + raw, ok := req.Data.([]interface{}) + if !ok { + return admin.NewInvalidAdminReqFormatError("input must be a JSON array of pattern strings") + } + if len(raw) == 0 { + return admin.NewInvalidAdminReqFormatError("input must not be empty") + } + + patterns := make([]string, 0, len(raw)) + for _, v := range raw { + pattern, ok := v.(string) + if !ok { + return admin.NewInvalidAdminReqFormatError("each element must be a string") + } + pattern = logging.NormalizePattern(strings.TrimSpace(pattern)) + if pattern == "*" { + if len(patterns) > 1 { + return admin.NewInvalidAdminReqErrorf("\"*\" must be the only pattern when resetting all components") + } + } else { + if err := logging.ValidatePattern(pattern); err != nil { + return admin.NewInvalidAdminReqErrorf("invalid pattern %q: %w", pattern, err) + } + } + patterns = append(patterns, pattern) + } + + req.ValidatorData = patterns + return nil +} + +// Handler removes the specified runtime overrides and returns "ok". +// +// No error returns are expected during normal operation. +func (r *ResetComponentLogLevelCommand) Handler(_ context.Context, req *admin.CommandRequest) (interface{}, error) { + patterns := req.ValidatorData.([]string) + if err := r.registry.Reset(patterns...); err != nil { + return nil, fmt.Errorf("failed to reset component log levels: %w", err) + } + return "ok", nil +} diff --git a/admin/commands/common/component_log_level_set.go b/admin/commands/common/component_log_level_set.go new file mode 100644 index 00000000000..79d53a922fb --- /dev/null +++ b/admin/commands/common/component_log_level_set.go @@ -0,0 +1,96 @@ +package common + +import ( + "context" + "fmt" + "strings" + + "github.com/rs/zerolog" + + "github.com/onflow/flow-go/admin" + "github.com/onflow/flow-go/admin/commands" + "github.com/onflow/flow-go/utils/logging" +) + +const ( + maxPatternLength = 1024 +) + +var _ commands.AdminCommand = (*SetComponentLogLevelCommand)(nil) + +// SetComponentLogLevelCommand sets the log level for one or more components identified by +// exact or wildcard patterns. Input is a JSON object mapping pattern to level string. +// +// Example input: +// +// {"hotstuff.voter": "debug", "network.*": "warn"} +type SetComponentLogLevelCommand struct { + registry *logging.LogRegistry +} + +// NewSetComponentLogLevelCommand constructs a SetComponentLogLevelCommand. +func NewSetComponentLogLevelCommand(registry *logging.LogRegistry) *SetComponentLogLevelCommand { + return &SetComponentLogLevelCommand{registry: registry} +} + +type parsedComponentLevel struct { + pattern string + level zerolog.Level +} + +// Validator validates that the input is a non-empty map of pattern → level string with +// recognisable level values. +// +// Returns [admin.InvalidAdminReqError] for invalid or malformed requests. +func (s *SetComponentLogLevelCommand) Validator(req *admin.CommandRequest) error { + raw, ok := req.Data.(map[string]interface{}) + if !ok { + return admin.NewInvalidAdminReqFormatError("input must be a JSON object mapping component pattern to level string") + } + if len(raw) == 0 { + return admin.NewInvalidAdminReqFormatError("input must not be empty") + } + + parsed := make([]parsedComponentLevel, 0, len(raw)) + for pattern, val := range raw { + levelStr, ok := val.(string) + if !ok { + return admin.NewInvalidAdminReqErrorf("level for %q must be a string", pattern) + } + level, err := zerolog.ParseLevel(levelStr) + if err != nil { + return admin.NewInvalidAdminReqErrorf("invalid level %q for component %q: %w", levelStr, pattern, err) + } + if len(pattern) > maxPatternLength { + return admin.NewInvalidAdminReqErrorf("pattern %q is too long (max %d characters)", pattern, maxPatternLength) + } + pattern = logging.NormalizePattern(strings.TrimSpace(pattern)) + if pattern == "*" { + return admin.NewInvalidAdminReqErrorf("global wildcard \"*\" is not a valid when setting component level logging. use set-log-level instead") + } + if err := logging.ValidatePattern(logging.NormalizePattern(pattern)); err != nil { + return admin.NewInvalidAdminReqErrorf("invalid pattern %q: %w", pattern, err) + } + + parsed = append(parsed, parsedComponentLevel{pattern: pattern, level: level}) + } + + req.ValidatorData = parsed + return nil +} + +// Handler applies the validated component level overrides and returns the updated patterns. +// +// No error returns are expected during normal operation. +func (s *SetComponentLogLevelCommand) Handler(_ context.Context, req *admin.CommandRequest) (interface{}, error) { + entries := req.ValidatorData.([]parsedComponentLevel) + + result := make(map[string]string, len(entries)) + for _, e := range entries { + if err := s.registry.SetLevel(e.pattern, e.level); err != nil { + return nil, fmt.Errorf("failed to set level for pattern %q: %w", e.pattern, err) + } + result[e.pattern] = fmt.Sprintf("set to %s", e.level) + } + return result, nil +} diff --git a/admin/commands/common/component_log_levels_get.go b/admin/commands/common/component_log_levels_get.go new file mode 100644 index 00000000000..e25349ecd8a --- /dev/null +++ b/admin/commands/common/component_log_levels_get.go @@ -0,0 +1,66 @@ +package common + +import ( + "context" + + "github.com/rs/zerolog" + + "github.com/onflow/flow-go/admin" + "github.com/onflow/flow-go/admin/commands" + "github.com/onflow/flow-go/utils/logging" +) + +var _ commands.AdminCommand = (*GetComponentLogLevelsCommand)(nil) + +// GetComponentLogLevelsCommand returns the current log level for every registered component +// and the global default. +type GetComponentLogLevelsCommand struct { + registry *logging.LogRegistry +} + +// NewGetComponentLogLevelsCommand constructs a GetComponentLogLevelsCommand. +func NewGetComponentLogLevelsCommand(registry *logging.LogRegistry) *GetComponentLogLevelsCommand { + return &GetComponentLogLevelsCommand{registry: registry} +} + +// Validator performs no validation — this command takes no input. +// +// No error returns are expected during normal operation. +func (g *GetComponentLogLevelsCommand) Validator(_ *admin.CommandRequest) error { + return nil +} + +// Handler returns a snapshot of all registered component log levels and the registry config. +// +// No error returns are expected during normal operation. +func (g *GetComponentLogLevelsCommand) Handler(_ context.Context, _ *admin.CommandRequest) (interface{}, error) { + _, levels := g.registry.Levels() + cfg := g.registry.Config() + + components := make(map[string]interface{}, len(levels)) + for id, cl := range levels { + components[id] = map[string]string{ + "level": zerolog.Level(cl.Level).String(), + "source": string(cl.Source), + } + } + + staticOverrides := make(map[string]string, len(cfg.StaticOverrides)) + for pattern, level := range cfg.StaticOverrides { + staticOverrides[pattern] = level.String() + } + + dynamicOverrides := make(map[string]string, len(cfg.DynamicOverrides)) + for pattern, level := range cfg.DynamicOverrides { + dynamicOverrides[pattern] = level.String() + } + + return map[string]interface{}{ + "config": map[string]interface{}{ + "default": cfg.Default.String(), + "static_overrides": staticOverrides, + "dynamic_overrides": dynamicOverrides, + }, + "components": components, + }, nil +} diff --git a/admin/commands/common/get_config.go b/admin/commands/common/config_get.go similarity index 100% rename from admin/commands/common/get_config.go rename to admin/commands/common/config_get.go diff --git a/admin/commands/common/set_config.go b/admin/commands/common/config_set.go similarity index 100% rename from admin/commands/common/set_config.go rename to admin/commands/common/config_set.go diff --git a/admin/commands/common/list_configs.go b/admin/commands/common/configs_list.go similarity index 100% rename from admin/commands/common/list_configs.go rename to admin/commands/common/configs_list.go diff --git a/admin/commands/common/set_golog_level.go b/admin/commands/common/golog_level_set.go similarity index 100% rename from admin/commands/common/set_golog_level.go rename to admin/commands/common/golog_level_set.go diff --git a/admin/commands/common/get_identity.go b/admin/commands/common/identity_get.go similarity index 100% rename from admin/commands/common/get_identity.go rename to admin/commands/common/identity_get.go diff --git a/admin/commands/common/set_log_level.go b/admin/commands/common/log_level_set.go similarity index 51% rename from admin/commands/common/set_log_level.go rename to admin/commands/common/log_level_set.go index a7812db8375..e95c1c4add4 100644 --- a/admin/commands/common/set_log_level.go +++ b/admin/commands/common/log_level_set.go @@ -8,22 +8,35 @@ import ( "github.com/onflow/flow-go/admin" "github.com/onflow/flow-go/admin/commands" + "github.com/onflow/flow-go/utils/logging" ) var _ commands.AdminCommand = (*SetLogLevelCommand)(nil) -type SetLogLevelCommand struct{} +// SetLogLevelCommand sets the global default log level. Components with per-component overrides +// (from the CLI flag or a prior set-component-log-level command) are unaffected. +type SetLogLevelCommand struct { + registry *logging.LogRegistry +} + +// NewSetLogLevelCommand constructs a SetLogLevelCommand. +func NewSetLogLevelCommand(registry *logging.LogRegistry) *SetLogLevelCommand { + return &SetLogLevelCommand{registry: registry} +} +// Handler sets the global default level via the registry. +// +// No error returns are expected during normal operation. func (s *SetLogLevelCommand) Handler(_ context.Context, req *admin.CommandRequest) (interface{}, error) { level := req.ValidatorData.(zerolog.Level) - zerolog.SetGlobalLevel(level) - - log.Info().Msgf("changed log level to %v", level) + s.registry.SetDefaultLevel(level) + log.Info().Msgf("changed default log level to %v", level) return "ok", nil } // Validator validates the request. -// Returns admin.InvalidAdminReqError for invalid/malformed requests. +// +// Returns [admin.InvalidAdminReqError] for invalid or malformed requests. func (s *SetLogLevelCommand) Validator(req *admin.CommandRequest) error { level, ok := req.Data.(string) if !ok { diff --git a/cmd/node_builder.go b/cmd/node_builder.go index bd1626cb627..4df57e8f9db 100644 --- a/cmd/node_builder.go +++ b/cmd/node_builder.go @@ -2,6 +2,7 @@ package cmd import ( "context" + "io" "time" "github.com/dgraph-io/badger/v2" @@ -29,6 +30,7 @@ import ( "github.com/onflow/flow-go/state/protocol/events" "github.com/onflow/flow-go/storage" bstorage "github.com/onflow/flow-go/storage/badger" + "github.com/onflow/flow-go/utils/logging" ) const NotSet = "not set" @@ -158,6 +160,7 @@ type BaseConfig struct { secretsDBEnabled bool InsecureSecretsDB bool level string + componentLogLevels string debugLogLimit uint32 metricsPort uint BootstrapDir string @@ -195,6 +198,8 @@ type NodeConfig struct { Cancel context.CancelFunc // cancel function for the context that is passed to the networking layer BaseConfig Logger zerolog.Logger + LogWriter io.Writer + LogRegistry *logging.LogRegistry NodeID flow.Identifier Me module.Local Tracer module.Tracer diff --git a/cmd/scaffold.go b/cmd/scaffold.go index 142f2d55c6d..bbf78f26999 100644 --- a/cmd/scaffold.go +++ b/cmd/scaffold.go @@ -176,6 +176,7 @@ func (fnb *FlowNodeBuilder) BaseFlags() { fnb.flags.StringVar(&fnb.BaseConfig.pebbleCheckpointsDir, "pebble-checkpoints-dir", defaultConfig.pebbleCheckpointsDir, "directory to store the checkpoints for the public pebble database (protocol state)") fnb.flags.StringVar(&fnb.BaseConfig.secretsdir, "secretsdir", defaultConfig.secretsdir, "directory to store private database (secrets)") fnb.flags.StringVarP(&fnb.BaseConfig.level, "loglevel", "l", defaultConfig.level, "level for logging output") + fnb.flags.StringVar(&fnb.BaseConfig.componentLogLevels, "component-log-levels", "", `per-component log levels, format: "component:level,prefix.*:level", e.g. "hotstuff:debug,network.*:warn"`) fnb.flags.Uint32Var(&fnb.BaseConfig.debugLogLimit, "debug-log-limit", defaultConfig.debugLogLimit, "max number of debug/trace log events per second") fnb.flags.UintVarP(&fnb.BaseConfig.metricsPort, "metricport", "m", defaultConfig.metricsPort, "port for /metrics endpoint") fnb.flags.BoolVar(&fnb.BaseConfig.profilerConfig.Enabled, "profiler-enabled", defaultConfig.profilerConfig.Enabled, "whether to enable the auto-profiler") @@ -910,12 +911,20 @@ func (fnb *FlowNodeBuilder) initLogger() error { return fmt.Errorf("invalid log level: %w", err) } - // Minimum log level is set to trace, then overridden by SetGlobalLevel. - // this allows admin commands to modify the level to any value during runtime + staticConfig, err := logging.ParseComponentLogLevels(fnb.BaseConfig.componentLogLevels) + if err != nil { + return fmt.Errorf("invalid --component-log-levels: %w", err) + } + + // Logger level is set to trace; all filtering is owned by LogRegistry. log = log.Level(zerolog.TraceLevel) - zerolog.SetGlobalLevel(lvl) - fnb.Logger = log + fnb.LogRegistry = logging.NewLogRegistry(fnb.LogWriter, lvl, staticConfig) + + // setup the main logger under a default component. this ensures any logs emitted under the default + // logger remain at the set global level, even if there are other components with lower levels. + // for details on why this is necessary, see the LogRegistry documentation. + fnb.Logger = fnb.LogRegistry.Logger(log, "default") return nil } @@ -1968,10 +1977,13 @@ func FlowNode(role string, opts ...Option) *FlowNodeBuilder { opt(config) } + logWriter := os.Stderr + builder := &FlowNodeBuilder{ NodeConfig: &NodeConfig{ BaseConfig: *config, - Logger: zerolog.New(os.Stderr), + Logger: zerolog.New(logWriter), + LogWriter: logWriter, PeerManagerDependencies: NewDependencyList(), ConfigManager: updatable_configs.NewManager(), }, @@ -2015,7 +2027,13 @@ func (fnb *FlowNodeBuilder) Initialize() error { func (fnb *FlowNodeBuilder) RegisterDefaultAdminCommands() { fnb.AdminCommand("set-log-level", func(config *NodeConfig) commands.AdminCommand { - return &common.SetLogLevelCommand{} + return common.NewSetLogLevelCommand(config.LogRegistry) + }).AdminCommand("set-component-log-level", func(config *NodeConfig) commands.AdminCommand { + return common.NewSetComponentLogLevelCommand(config.LogRegistry) + }).AdminCommand("reset-component-log-level", func(config *NodeConfig) commands.AdminCommand { + return common.NewResetComponentLogLevelCommand(config.LogRegistry) + }).AdminCommand("get-component-log-levels", func(config *NodeConfig) commands.AdminCommand { + return common.NewGetComponentLogLevelsCommand(config.LogRegistry) }).AdminCommand("set-golog-level", func(config *NodeConfig) commands.AdminCommand { return &common.SetGologLevelCommand{} }).AdminCommand("get-config", func(config *NodeConfig) commands.AdminCommand { diff --git a/utils/logging/README.md b/utils/logging/README.md new file mode 100644 index 00000000000..01797485058 --- /dev/null +++ b/utils/logging/README.md @@ -0,0 +1,58 @@ +# logging + +Package `logging` provides per-component log level control for Flow nodes via `LogRegistry`. + +## Overview + +Each component registers once at startup by calling `Logger`, receiving a `zerolog.Logger` +backed by a per-component writer. The registry controls that writer's level at runtime, so +level changes take effect immediately on all loggers derived from a registered component — +including child loggers created with `.With()`. + +The registry maintains `zerolog.GlobalLevel` as the minimum of all component levels to +preserve zerolog's pre-event-creation short-circuit optimisation. + +## Component IDs + +Component IDs are dot-separated lowercase strings, e.g. `"hotstuff"`, +`"hotstuff.voter"`, `"hotstuff.voter.timer"`. The hierarchy is a naming convention only — +the registry stores every ID as a flat key. + +Wildcard patterns (`"prefix.*"`) match any ID that starts with `prefix.`, including deeply +nested ones. `"hotstuff.*"` matches `"hotstuff.voter"` and `"hotstuff.voter.timer"` but +**not** `"hotstuff"` itself. + +## Level resolution priority + +For each component, the effective level is resolved in this order: + +1. Runtime override — exact pattern (via `SetLevel` or admin command) +2. Runtime override — most-specific wildcard +3. Static config — exact pattern (`--component-log-levels` flag) +4. Static config — most-specific wildcard +5. Global default + +## Usage + +```go +// Construct once at node startup. +registry := logging.NewLogRegistry(os.Stderr, zerolog.InfoLevel, staticConfig) + +// Register a root component. +logger := registry.Logger(node.Logger, "hotstuff") + +// Register a child, inheriting parent context fields. +child := registry.Logger(logger, "hotstuff.voter") + +// Adjust levels at runtime (e.g. from an admin command). +registry.SetLevel("hotstuff.*", zerolog.DebugLevel) // all hotstuff children → debug +registry.SetLevel("hotstuff", zerolog.WarnLevel) // hotstuff root → warn + +// Remove runtime overrides, falling back to static config or default. +registry.Reset("hotstuff.*") +registry.Reset("*") // reset everything + +// Inspect current state. +defaultLevel, components := registry.Levels() +cfg := registry.Config() +``` diff --git a/utils/logging/component_writer.go b/utils/logging/component_writer.go new file mode 100644 index 00000000000..545e1093ff5 --- /dev/null +++ b/utils/logging/component_writer.go @@ -0,0 +1,56 @@ +package logging + +import ( + "io" + "sync/atomic" + + "github.com/rs/zerolog" +) + +// componentLevelWriter is a zerolog.LevelWriter that filters log events below a dynamically +// controlled level. The level is read atomically on every write, enabling lock-free updates +// from admin commands without any coordination with writers. +// +// All exported methods are safe for concurrent access. +type componentLevelWriter struct { + level *atomic.Int32 + delegate zerolog.LevelWriter +} + +// NewComponentLevelWriter returns a zerolog.LevelWriter that forwards events to delegate only +// when the event level is at or above the value stored in level. +func NewComponentLevelWriter(level *atomic.Int32, delegate zerolog.LevelWriter) zerolog.LevelWriter { + return &componentLevelWriter{level: level, delegate: delegate} +} + +// Write forwards p to the delegate unconditionally. This path is only taken by callers that +// bypass zerolog's level-aware dispatch; in normal zerolog usage WriteLevel is called instead. +// +// No error returns are expected during normal operation. +func (w *componentLevelWriter) Write(p []byte) (int, error) { + return w.delegate.Write(p) +} + +// WriteLevel forwards p to the delegate if l is at or above the configured level. If the +// event is filtered, WriteLevel returns (len(p), nil) without writing — matching zerolog's +// discard convention. +// +// No error returns are expected during normal operation. +func (w *componentLevelWriter) WriteLevel(l zerolog.Level, p []byte) (int, error) { + if l < zerolog.Level(w.level.Load()) { + return len(p), nil + } + return w.delegate.WriteLevel(l, p) +} + +// NoopLevelWriter wraps an io.Writer as a zerolog.LevelWriter, ignoring the level argument. +// Intended for tests. +func NoopLevelWriter(w io.Writer) zerolog.LevelWriter { + return &noopLevelWriter{w} +} + +type noopLevelWriter struct{ io.Writer } + +func (n *noopLevelWriter) WriteLevel(_ zerolog.Level, p []byte) (int, error) { + return n.Write(p) +} diff --git a/utils/logging/component_writer_test.go b/utils/logging/component_writer_test.go new file mode 100644 index 00000000000..0f0f3ec582b --- /dev/null +++ b/utils/logging/component_writer_test.go @@ -0,0 +1,69 @@ +package logging_test + +import ( + "bytes" + "sync/atomic" + "testing" + + "github.com/rs/zerolog" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + + "github.com/onflow/flow-go/utils/logging" +) + +// TestComponentLevelWriter_FiltersBelow verifies that events below the configured level +// are silently discarded without writing to the delegate. +func TestComponentLevelWriter_FiltersBelow(t *testing.T) { + var buf bytes.Buffer + delegate := logging.NoopLevelWriter(&buf) + + var lvl atomic.Int32 + lvl.Store(int32(zerolog.InfoLevel)) + + w := logging.NewComponentLevelWriter(&lvl, delegate) + n, err := w.WriteLevel(zerolog.DebugLevel, []byte(`{"level":"debug","msg":"hi"}`)) + require.NoError(t, err) + assert.Equal(t, 0, buf.Len(), "expected nothing written for debug below info") + assert.Greater(t, n, 0, "expected non-zero n even on discard") +} + +// TestComponentLevelWriter_PassesAtOrAbove verifies that events at or above the configured +// level are forwarded to the delegate unchanged. +func TestComponentLevelWriter_PassesAtOrAbove(t *testing.T) { + var buf bytes.Buffer + delegate := logging.NoopLevelWriter(&buf) + + var lvl atomic.Int32 + lvl.Store(int32(zerolog.InfoLevel)) + + w := logging.NewComponentLevelWriter(&lvl, delegate) + msg := []byte(`{"level":"warn","msg":"hi"}`) + _, err := w.WriteLevel(zerolog.WarnLevel, msg) + require.NoError(t, err) + assert.Equal(t, msg, buf.Bytes()) +} + +// TestComponentLevelWriter_AtomicUpdate verifies that updating the atomic level is +// immediately reflected in subsequent writes without re-creating the writer. +func TestComponentLevelWriter_AtomicUpdate(t *testing.T) { + var buf bytes.Buffer + delegate := logging.NoopLevelWriter(&buf) + + var lvl atomic.Int32 + lvl.Store(int32(zerolog.InfoLevel)) + + w := logging.NewComponentLevelWriter(&lvl, delegate) + + // debug blocked at info + _, err := w.WriteLevel(zerolog.DebugLevel, []byte(`{"level":"debug"}`)) + require.NoError(t, err) + assert.Equal(t, 0, buf.Len()) + + // lower to debug + lvl.Store(int32(zerolog.DebugLevel)) + msg := []byte(`{"level":"debug","msg":"now visible"}`) + _, err = w.WriteLevel(zerolog.DebugLevel, msg) + require.NoError(t, err) + assert.Equal(t, msg, buf.Bytes()) +} diff --git a/utils/logging/export_test.go b/utils/logging/export_test.go new file mode 100644 index 00000000000..da6e9b130a9 --- /dev/null +++ b/utils/logging/export_test.go @@ -0,0 +1,4 @@ +package logging + +// BestWildcardMatch exports bestWildcardMatch for use in external test packages. +var BestWildcardMatch = bestWildcardMatch diff --git a/utils/logging/parse.go b/utils/logging/parse.go new file mode 100644 index 00000000000..43d81dfd309 --- /dev/null +++ b/utils/logging/parse.go @@ -0,0 +1,42 @@ +package logging + +import ( + "fmt" + "strings" + + "github.com/rs/zerolog" +) + +// ParseComponentLogLevels parses the --component-log-levels flag value into a map of +// component pattern to zerolog.Level. Component patterns are normalized to lowercase. +// +// Format: "component:level,prefix.*:level" +// Example: "hotstuff:debug,network.*:warn" +// +// Any error indicates the entry is invalid. +func ParseComponentLogLevels(s string) (map[string]zerolog.Level, error) { + result := make(map[string]zerolog.Level) + if s == "" { + return result, nil + } + for entry := range strings.SplitSeq(s, ",") { + if strings.Count(entry, ":") != 1 { + return nil, fmt.Errorf("invalid component log level entry %q: expected format component:level", entry) + } + parts := strings.SplitN(entry, ":", 2) + component := NormalizePattern(strings.TrimSpace(parts[0])) + levelStr := strings.ToLower(strings.TrimSpace(parts[1])) + if component == "" { + return nil, fmt.Errorf("invalid component log level entry %q: component name must not be empty", entry) + } + if err := ValidatePattern(component); err != nil { + return nil, fmt.Errorf("invalid component log level entry %q: %w", entry, err) + } + level, err := zerolog.ParseLevel(levelStr) + if err != nil { + return nil, fmt.Errorf("invalid log level %q for component %q: %w", levelStr, component, err) + } + result[component] = level + } + return result, nil +} diff --git a/utils/logging/parse_test.go b/utils/logging/parse_test.go new file mode 100644 index 00000000000..328b5256103 --- /dev/null +++ b/utils/logging/parse_test.go @@ -0,0 +1,47 @@ +package logging_test + +import ( + "testing" + + "github.com/rs/zerolog" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + + "github.com/onflow/flow-go/utils/logging" +) + +func TestParseComponentLogLevels_Empty(t *testing.T) { + result, err := logging.ParseComponentLogLevels("") + require.NoError(t, err) + assert.Empty(t, result) +} + +func TestParseComponentLogLevels_Single(t *testing.T) { + result, err := logging.ParseComponentLogLevels("hotstuff:debug") + require.NoError(t, err) + assert.Equal(t, map[string]zerolog.Level{"hotstuff": zerolog.DebugLevel}, result) +} + +func TestParseComponentLogLevels_Multiple(t *testing.T) { + result, err := logging.ParseComponentLogLevels("hotstuff:debug,network.*:warn") + require.NoError(t, err) + assert.Equal(t, map[string]zerolog.Level{ + "hotstuff": zerolog.DebugLevel, + "network.*": zerolog.WarnLevel, + }, result) +} + +func TestParseComponentLogLevels_InvalidLevel(t *testing.T) { + _, err := logging.ParseComponentLogLevels("hotstuff:badlevel") + require.Error(t, err) +} + +func TestParseComponentLogLevels_MissingColon(t *testing.T) { + _, err := logging.ParseComponentLogLevels("hotstuffdebug") + require.Error(t, err) +} + +func TestParseComponentLogLevels_EmptyComponent(t *testing.T) { + _, err := logging.ParseComponentLogLevels(":debug") + require.Error(t, err) +} diff --git a/utils/logging/registry.go b/utils/logging/registry.go new file mode 100644 index 00000000000..d00dbbb2e78 --- /dev/null +++ b/utils/logging/registry.go @@ -0,0 +1,331 @@ +package logging + +import ( + "fmt" + "io" + "maps" + "strings" + "sync" + "sync/atomic" + + "github.com/rs/zerolog" +) + +// LevelSource describes where a component's effective level originated. +type LevelSource string + +const ( + // LevelSourceOverride indicates the level was set by an admin command (exact pattern). + LevelSourceOverride LevelSource = "override" + // LevelSourceOverrideWildcard indicates the level was set by an admin command (wildcard pattern). + LevelSourceOverrideWildcard LevelSource = "override-wildcard" + // LevelSourceStatic indicates the level was set by the --component-log-levels CLI flag (exact). + LevelSourceStatic LevelSource = "static" + // LevelSourceStaticWildcard indicates the level was set by the --component-log-levels CLI flag (wildcard). + LevelSourceStaticWildcard LevelSource = "static-wildcard" + // LevelSourceDefault indicates the level falls back to the global default. + LevelSourceDefault LevelSource = "default" +) + +// ComponentLevel holds the effective log level and its source for a registered component. +type ComponentLevel struct { + Level zerolog.Level + Source LevelSource +} + +// RegistryConfig is a snapshot of the registry's configuration at a point in time. +type RegistryConfig struct { + // Default is the global default log level applied to components with no specific override. + Default zerolog.Level + // StaticOverrides are patterns and levels set at startup via the --component-log-levels flag. + StaticOverrides map[string]zerolog.Level + // DynamicOverrides are patterns and levels set at runtime via admin commands. + DynamicOverrides map[string]zerolog.Level +} + +// LogRegistry manages per-component log levels. Components register by calling Logger with a +// unique ID; the returned zerolog.Logger is backed by a componentLevelWriter whose level the +// registry controls. All registered loggers derived from a component logger via With() share the +// same componentLevelWriter and automatically reflect level changes. +// +// The registry owns zerolog.SetGlobalLevel, maintaining it as the minimum of all configured +// component levels to preserve zerolog's pre-creation event optimisation. A consequence of this is +// that any logger NOT registered with the registry will emit logs at the lowest level of any +// registered component, rather than the global default. To avoid this, the top-level node logger +// should be registered under a "default" component so that its level is independently controlled +// by a componentLevelWriter, regardless of what other components are configured to. +// +// All exported methods are safe for concurrent access. +type LogRegistry struct { + // these fields are immutable after construction + baseWriter zerolog.LevelWriter // underlying output; wrapped per component + staticConfig map[string]zerolog.Level // from CLI flag; never mutates after construction + + // mu protects all mutable fields listed below + mu sync.RWMutex + + globalDefault zerolog.Level // set during construction; updated by SetDefaultLevel + overrides map[string]zerolog.Level // from admin commands; cleared on reset + registered map[string]*atomic.Int32 // componentID → current effective level +} + +// NewLogRegistry constructs a LogRegistry. baseWriter is the underlying output; it is wrapped +// per component. staticConfig is the parsed --component-log-levels flag; it must not be mutated +// after construction. +func NewLogRegistry( + baseWriter io.Writer, + globalDefault zerolog.Level, + staticConfig map[string]zerolog.Level, +) *LogRegistry { + static := make(map[string]zerolog.Level, len(staticConfig)) + maps.Copy(static, staticConfig) + + zerolog.SetGlobalLevel(globalDefault) + + return &LogRegistry{ + baseWriter: toLevelWriter(baseWriter), + globalDefault: globalDefault, + staticConfig: static, + overrides: make(map[string]zerolog.Level), + registered: make(map[string]*atomic.Int32), + } +} + +// Logger registers componentID and returns a zerolog.Logger derived from parent, +// preserving all of parent's context fields while backing the logger with a fresh +// componentLevelWriter for this component. +// +// Component IDs use dot-separated segments to express hierarchy, e.g. "hotstuff", +// "hotstuff.voter", "hotstuff.voter.timer". This hierarchy is purely a naming convention +// for level targeting — the registry treats every ID as a flat key. Hierarchy only matters +// when applying wildcard patterns via [LogRegistry.SetLevel] or the --component-log-levels +// flag: the pattern "hotstuff.*" matches any ID whose prefix is "hotstuff.", such as +// "hotstuff.voter" and "hotstuff.voter.timer", but not "hotstuff" itself. +// +// Use the node's top-level logger as parent at the root level: +// +// logger := registry.Logger(node.Logger, "hotstuff") +// +// Pass an already-enriched logger to inherit accumulated context down a hierarchy: +// +// enriched := logger.With().Uint64("view", view).Logger() +// child := registry.Logger(enriched, "hotstuff.voter") +// +// Panics if componentID is already registered or invalid — both are programming errors. +// componentID is normalized to lowercase before registration. +func (r *LogRegistry) Logger(parent zerolog.Logger, componentID string) zerolog.Logger { + r.mu.Lock() + defer r.mu.Unlock() + + componentID = NormalizePattern(componentID) + if err := ValidateComponentID(componentID); err != nil { + panic(fmt.Sprintf("log registry: %s", err)) + } + if _, exists := r.registered[componentID]; exists { + panic(fmt.Sprintf("log registry: component %q already registered", componentID)) + } + + level := r.resolve(componentID) + atomicLevel := &atomic.Int32{} + atomicLevel.Store(int32(level)) + r.registered[componentID] = atomicLevel + + w := NewComponentLevelWriter(atomicLevel, r.baseWriter) + r.updateGlobalLevel() + return parent.Output(w) +} + +// EffectiveLevel returns the current effective log level for a registered component. +// Returns [zerolog.Disabled] if not registered. +// componentID is normalized to lowercase before lookup. +func (r *LogRegistry) EffectiveLevel(componentID string) zerolog.Level { + r.mu.RLock() + defer r.mu.RUnlock() + if al, ok := r.registered[NormalizePattern(componentID)]; ok { + return zerolog.Level(al.Load()) + } + return zerolog.Disabled +} + +// updateGlobalLevel sets zerolog.GlobalLevel to min(globalDefault, all component levels). +// +// Not concurrency safe +func (r *LogRegistry) updateGlobalLevel() { + min := r.globalDefault + for _, al := range r.registered { + if l := zerolog.Level(al.Load()); l < min { + min = l + } + } + zerolog.SetGlobalLevel(min) +} + +// SetLevel applies level to all registered components matching pattern. pattern may be an +// exact component ID or a wildcard ("prefix.*"). The new override is stored and takes effect +// immediately on all matching registered components. +// pattern is normalized to lowercase before storage. +func (r *LogRegistry) SetLevel(pattern string, level zerolog.Level) error { + pattern = NormalizePattern(pattern) + if err := ValidatePattern(pattern); err != nil { + return err + } + + r.mu.Lock() + defer r.mu.Unlock() + r.overrides[pattern] = level + r.applyToMatching(pattern) + r.updateGlobalLevel() + return nil +} + +// Reset removes runtime overrides matching each pattern in patterns and re-resolves affected +// components from static config and globalDefault. Passing ["*"] removes all overrides and +// resets every registered component. Each pattern is normalized to lowercase. +func (r *LogRegistry) Reset(patterns ...string) error { + for i, pattern := range patterns { + normalized := NormalizePattern(pattern) + if normalized == "*" { + if len(patterns) > 1 { + return fmt.Errorf("\"*\" must be the only pattern when resetting all components") + } + } else if err := ValidatePattern(normalized); err != nil { + return fmt.Errorf("pattern %d is invalid: %w", i, err) + } + patterns[i] = normalized + } + + r.mu.Lock() + defer r.mu.Unlock() + + for _, pattern := range patterns { + if pattern == "*" { + r.overrides = make(map[string]zerolog.Level) + for id, al := range r.registered { + al.Store(int32(r.resolve(id))) + } + break + } + delete(r.overrides, pattern) + r.applyToMatching(pattern) + } + r.updateGlobalLevel() + return nil +} + +// SetDefaultLevel updates the global default and re-resolves all registered components. +// Per-component overrides (runtime or static) take priority and are preserved. +func (r *LogRegistry) SetDefaultLevel(level zerolog.Level) { + r.mu.Lock() + defer r.mu.Unlock() + + r.globalDefault = level + for id, al := range r.registered { + al.Store(int32(r.resolve(id))) + } + r.updateGlobalLevel() +} + +// Levels returns the current globalDefault and a snapshot of every registered component's +// effective level and source. +func (r *LogRegistry) Levels() (zerolog.Level, map[string]ComponentLevel) { + r.mu.RLock() + defer r.mu.RUnlock() + + result := make(map[string]ComponentLevel, len(r.registered)) + for id := range r.registered { + level, source := r.resolveWithSource(id) + result[id] = ComponentLevel{Level: level, Source: source} + } + return r.globalDefault, result +} + +// Config returns a snapshot of the registry's current configuration. +func (r *LogRegistry) Config() RegistryConfig { + r.mu.RLock() + defer r.mu.RUnlock() + + static := make(map[string]zerolog.Level, len(r.staticConfig)) + maps.Copy(static, r.staticConfig) + + dynamic := make(map[string]zerolog.Level, len(r.overrides)) + maps.Copy(dynamic, r.overrides) + + return RegistryConfig{ + Default: r.globalDefault, + StaticOverrides: static, + DynamicOverrides: dynamic, + } +} + +// resolve returns the effective level for componentID using the priority order: +// override exact > override wildcard (most specific) > static exact > static wildcard > globalDefault. +// +// Not concurrency safe +func (r *LogRegistry) resolve(componentID string) zerolog.Level { + level, _ := r.resolveWithSource(componentID) + return level +} + +// resolveWithSource is like resolve but also returns the LevelSource for reporting. +// +// Not concurrency safe +func (r *LogRegistry) resolveWithSource(id string) (zerolog.Level, LevelSource) { + if level, ok := r.overrides[id]; ok { + return level, LevelSourceOverride + } + if level, ok := bestWildcardMatch(r.overrides, id); ok { + return level, LevelSourceOverrideWildcard + } + if level, ok := r.staticConfig[id]; ok { + return level, LevelSourceStatic + } + if level, ok := bestWildcardMatch(r.staticConfig, id); ok { + return level, LevelSourceStaticWildcard + } + return r.globalDefault, LevelSourceDefault +} + +// applyToMatching re-resolves all registered components matched by pattern. +// +// Not concurrency safe +func (r *LogRegistry) applyToMatching(pattern string) { + if prefix, ok := strings.CutSuffix(pattern, ".*"); ok { + for id, al := range r.registered { + if strings.HasPrefix(id, prefix+".") { + al.Store(int32(r.resolve(id))) + } + } + } else { + if al, ok := r.registered[pattern]; ok { + al.Store(int32(r.resolve(pattern))) + } + } +} + +// bestWildcardMatch finds the most specific "prefix.*" wildcard in config that matches id. +// Returns the level and true if found, zero value and false otherwise. +func bestWildcardMatch(config map[string]zerolog.Level, id string) (zerolog.Level, bool) { + var bestPrefix string + var bestLevel zerolog.Level + found := false + for pattern, level := range config { + prefix, ok := strings.CutSuffix(pattern, ".*") + if !ok { + continue + } + if strings.HasPrefix(id, prefix+".") && len(prefix) > len(bestPrefix) { + bestPrefix = prefix + bestLevel = level + found = true + } + } + return bestLevel, found +} + +// toLevelWriter wraps w as a zerolog.LevelWriter if it does not already implement the interface. +func toLevelWriter(w io.Writer) zerolog.LevelWriter { + if lw, ok := w.(zerolog.LevelWriter); ok { + return lw + } + return NoopLevelWriter(w) +} diff --git a/utils/logging/registry_bench_test.go b/utils/logging/registry_bench_test.go new file mode 100644 index 00000000000..cff003814fd --- /dev/null +++ b/utils/logging/registry_bench_test.go @@ -0,0 +1,121 @@ +package logging_test + +import ( + "io" + "testing" + + "github.com/rs/zerolog" + + "github.com/onflow/flow-go/utils/logging" +) + +// benchRegistry returns a LogRegistry and a base logger that discard all output, +// suitable for benchmarks where I/O cost should not affect results. +func benchRegistry(defaultLevel zerolog.Level) (*logging.LogRegistry, zerolog.Logger) { + r := logging.NewLogRegistry(io.Discard, defaultLevel, nil) + base := zerolog.New(io.Discard).Level(zerolog.TraceLevel) + return r, base +} + +// BenchmarkSuppressedEvent compares a debug event suppressed at info level between +// a plain zerolog logger and a registry-backed logger. +func BenchmarkSuppressedEvent(b *testing.B) { + b.Run("baseline", func(b *testing.B) { + logger := zerolog.New(io.Discard).Level(zerolog.InfoLevel) + suppressEvent(b, logger) + }) + b.Run("registry", func(b *testing.B) { + r, base := benchRegistry(zerolog.InfoLevel) + logger := r.Logger(base, "hotstuff") + suppressEvent(b, logger) + }) +} + +// BenchmarkActiveEvent compares an info event that passes through to the discard sink +// between a plain zerolog logger and a registry-backed logger. +func BenchmarkActiveEvent(b *testing.B) { + b.Run("baseline", func(b *testing.B) { + logger := zerolog.New(io.Discard).Level(zerolog.InfoLevel) + activeEvent(b, logger) + }) + b.Run("registry", func(b *testing.B) { + r, base := benchRegistry(zerolog.InfoLevel) + logger := r.Logger(base, "hotstuff") + activeEvent(b, logger) + }) +} + +// BenchmarkActiveEvent_Parallel compares concurrent logging throughput across two +// independent loggers between plain zerolog and the registry. +func BenchmarkActiveEvent_Parallel(b *testing.B) { + b.Run("baseline", func(b *testing.B) { + loggerA := zerolog.New(io.Discard).Level(zerolog.InfoLevel) + loggerB := zerolog.New(io.Discard).Level(zerolog.InfoLevel) + parallelTest(b, loggerA, loggerB) + }) + b.Run("registry", func(b *testing.B) { + r, base := benchRegistry(zerolog.InfoLevel) + loggerA := r.Logger(base, "component-a") + loggerB := r.Logger(base, "component-b") + parallelTest(b, loggerA, loggerB) + }) +} + +// BenchmarkChildLogger_SuppressedEvent compares suppression cost for a child logger +// derived via With() between plain zerolog and the registry. +func BenchmarkChildLogger_SuppressedEvent(b *testing.B) { + b.Run("baseline", func(b *testing.B) { + parent := zerolog.New(io.Discard).Level(zerolog.InfoLevel) + child := parent.With().Str("sub", "voter").Logger() + suppressEvent(b, child) + }) + b.Run("registry", func(b *testing.B) { + r, base := benchRegistry(zerolog.InfoLevel) + parent := r.Logger(base, "hotstuff") + child := parent.With().Str("sub", "voter").Logger() + suppressEvent(b, child) + }) +} + +// BenchmarkChildLogger_ActiveEvent compares active event cost for a child logger +// derived via With() between plain zerolog and the registry. +func BenchmarkChildLogger_ActiveEvent(b *testing.B) { + b.Run("baseline", func(b *testing.B) { + parent := zerolog.New(io.Discard).Level(zerolog.InfoLevel) + child := parent.With().Str("sub", "voter").Logger() + activeEvent(b, child) + }) + b.Run("registry", func(b *testing.B) { + r, base := benchRegistry(zerolog.InfoLevel) + parent := r.Logger(base, "hotstuff") + child := parent.With().Str("sub", "voter").Logger() + activeEvent(b, child) + }) +} + +func suppressEvent(b *testing.B, logger zerolog.Logger) { + for b.Loop() { + logger.Debug().Msg("suppressed") + } +} + +func activeEvent(b *testing.B, logger zerolog.Logger) { + for b.Loop() { + logger.Info().Msg("active") + } +} + +func parallelTest(b *testing.B, loggerA, loggerB zerolog.Logger) { + b.ResetTimer() + b.RunParallel(func(pb *testing.PB) { + i := 0 + for pb.Next() { + if i%2 == 0 { + loggerA.Info().Msg("a") + } else { + loggerB.Info().Msg("b") + } + i++ + } + }) +} diff --git a/utils/logging/registry_test.go b/utils/logging/registry_test.go new file mode 100644 index 00000000000..9eceb40a604 --- /dev/null +++ b/utils/logging/registry_test.go @@ -0,0 +1,510 @@ +package logging_test + +import ( + "bytes" + "os" + "testing" + + "github.com/rs/zerolog" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + + "github.com/onflow/flow-go/utils/logging" +) + +func testRegistry(t *testing.T, defaultLevel zerolog.Level, static map[string]zerolog.Level) (*logging.LogRegistry, zerolog.Logger) { + t.Helper() + + originalGlobalLevel := zerolog.GlobalLevel() + t.Cleanup(func() { zerolog.SetGlobalLevel(originalGlobalLevel) }) + + r := logging.NewLogRegistry(os.Stderr, defaultLevel, static) + return r, zerolog.New(os.Stderr).Level(zerolog.TraceLevel) +} + +// testRegistryWithBuffer creates a LogRegistry backed by a bytes.Buffer for output inspection. +func testRegistryWithBuffer(t *testing.T, defaultLevel zerolog.Level) (*logging.LogRegistry, zerolog.Logger, *bytes.Buffer) { + t.Helper() + + originalGlobalLevel := zerolog.GlobalLevel() + t.Cleanup(func() { zerolog.SetGlobalLevel(originalGlobalLevel) }) + + var buf bytes.Buffer + baseLogger := zerolog.New(&buf).Level(zerolog.TraceLevel) + r := logging.NewLogRegistry(&buf, defaultLevel, nil) + return r, baseLogger, &buf +} + +// TestLogRegistry_RegisterReturnsLogger verifies Logger() returns a usable zerolog.Logger. +func TestLogRegistry_RegisterReturnsLogger(t *testing.T) { + r, log := testRegistry(t, zerolog.InfoLevel, nil) + logger := r.Logger(log, "hotstuff") + logger.Info().Msg("test") +} + +// TestLogRegistry_DuplicateRegisterPanics verifies that registering the same ID twice panics. +func TestLogRegistry_DuplicateRegisterPanics(t *testing.T) { + r, log := testRegistry(t, zerolog.InfoLevel, nil) + r.Logger(log, "hotstuff") + require.Panics(t, func() { r.Logger(log, "hotstuff") }) +} + +// TestLogRegistry_ResolvesDefaultLevel verifies that a component with no static config +// or override resolves to globalDefault. +func TestLogRegistry_ResolvesDefaultLevel(t *testing.T) { + r, log := testRegistry(t, zerolog.WarnLevel, nil) + r.Logger(log, "hotstuff") + assert.Equal(t, zerolog.WarnLevel, r.EffectiveLevel("hotstuff")) +} + +// TestLogRegistry_ResolvesStaticExact verifies that a static exact match beats globalDefault. +func TestLogRegistry_ResolvesStaticExact(t *testing.T) { + r, log := testRegistry(t, zerolog.InfoLevel, map[string]zerolog.Level{ + "hotstuff": zerolog.DebugLevel, + }) + r.Logger(log, "hotstuff") + assert.Equal(t, zerolog.DebugLevel, r.EffectiveLevel("hotstuff")) +} + +// TestLogRegistry_ResolvesStaticWildcard verifies that a static wildcard match is applied +// when no exact match exists. +func TestLogRegistry_ResolvesStaticWildcard(t *testing.T) { + r, log := testRegistry(t, zerolog.InfoLevel, map[string]zerolog.Level{ + "hotstuff.*": zerolog.DebugLevel, + }) + r.Logger(log, "hotstuff.voter") + assert.Equal(t, zerolog.DebugLevel, r.EffectiveLevel("hotstuff.voter")) +} + +// TestLogRegistry_StaticWildcardDoesNotMatchParent verifies that "hotstuff.*" does not +// match "hotstuff" itself. +func TestLogRegistry_StaticWildcardDoesNotMatchParent(t *testing.T) { + r, log := testRegistry(t, zerolog.InfoLevel, map[string]zerolog.Level{ + "hotstuff.*": zerolog.DebugLevel, + }) + r.Logger(log, "hotstuff") + assert.Equal(t, zerolog.InfoLevel, r.EffectiveLevel("hotstuff")) +} + +// TestLogRegistry_MostSpecificWildcardWins verifies that the longest matching prefix +// wildcard takes priority. +func TestLogRegistry_MostSpecificWildcardWins(t *testing.T) { + r, log := testRegistry(t, zerolog.InfoLevel, map[string]zerolog.Level{ + "hotstuff.*": zerolog.DebugLevel, + "hotstuff.voter.*": zerolog.WarnLevel, + }) + r.Logger(log, "hotstuff.voter.timer") + assert.Equal(t, zerolog.WarnLevel, r.EffectiveLevel("hotstuff.voter.timer")) +} + +// TestLogRegistry_GlobalLevelSetToMinimum verifies that zerolog.GlobalLevel is set to +// the minimum of all component levels after registration. +func TestLogRegistry_GlobalLevelSetToMinimum(t *testing.T) { + r, log := testRegistry(t, zerolog.InfoLevel, map[string]zerolog.Level{ + "hotstuff": zerolog.DebugLevel, + }) + r.Logger(log, "hotstuff") + r.Logger(log, "network") + assert.Equal(t, zerolog.DebugLevel, zerolog.GlobalLevel()) +} + +// TestLogRegistry_SetLevelExact verifies that SetLevel with an exact pattern updates only +// the matching registered component. +func TestLogRegistry_SetLevelExact(t *testing.T) { + r, log := testRegistry(t, zerolog.InfoLevel, nil) + r.Logger(log, "hotstuff") + r.Logger(log, "hotstuff.voter") + + err := r.SetLevel("hotstuff", zerolog.DebugLevel) + require.NoError(t, err) + + assert.Equal(t, zerolog.DebugLevel, r.EffectiveLevel("hotstuff")) + assert.Equal(t, zerolog.InfoLevel, r.EffectiveLevel("hotstuff.voter")) +} + +// TestLogRegistry_SetLevelWildcard verifies that SetLevel with a wildcard pattern updates +// all matching children but not the parent. +func TestLogRegistry_SetLevelWildcard(t *testing.T) { + r, log := testRegistry(t, zerolog.InfoLevel, nil) + r.Logger(log, "hotstuff") + r.Logger(log, "hotstuff.voter") + r.Logger(log, "hotstuff.pacemaker") + r.Logger(log, "network") + + err := r.SetLevel("hotstuff.*", zerolog.DebugLevel) + require.NoError(t, err) + + assert.Equal(t, zerolog.InfoLevel, r.EffectiveLevel("hotstuff")) + assert.Equal(t, zerolog.DebugLevel, r.EffectiveLevel("hotstuff.voter")) + assert.Equal(t, zerolog.DebugLevel, r.EffectiveLevel("hotstuff.pacemaker")) + assert.Equal(t, zerolog.InfoLevel, r.EffectiveLevel("network")) +} + +// TestLogRegistry_SetLevelMoreSpecificOverrideNotClobbered verifies that a more specific +// override is not overwritten by a less specific wildcard set. +func TestLogRegistry_SetLevelMoreSpecificOverrideNotClobbered(t *testing.T) { + r, log := testRegistry(t, zerolog.InfoLevel, nil) + r.Logger(log, "hotstuff.voter") + + err := r.SetLevel("hotstuff.voter", zerolog.WarnLevel) // exact override first + require.NoError(t, err) + err = r.SetLevel("hotstuff.*", zerolog.DebugLevel) // wildcard applied second + require.NoError(t, err) + + // exact override beats wildcard + assert.Equal(t, zerolog.WarnLevel, r.EffectiveLevel("hotstuff.voter")) +} + +// TestLogRegistry_SetLevelUpdatesGlobalLevel verifies that lowering a component level +// also lowers zerolog.GlobalLevel. +func TestLogRegistry_SetLevelUpdatesGlobalLevel(t *testing.T) { + r, log := testRegistry(t, zerolog.InfoLevel, nil) + r.Logger(log, "hotstuff") + + err := r.SetLevel("hotstuff", zerolog.DebugLevel) + require.NoError(t, err) + assert.Equal(t, zerolog.DebugLevel, zerolog.GlobalLevel()) +} + +// TestLogRegistry_ResetExact verifies that Reset removes a runtime override, restoring +// the component to its static config or global default. +func TestLogRegistry_ResetExact(t *testing.T) { + r, log := testRegistry(t, zerolog.InfoLevel, map[string]zerolog.Level{ + "hotstuff": zerolog.WarnLevel, + }) + r.Logger(log, "hotstuff") + err := r.SetLevel("hotstuff", zerolog.DebugLevel) + require.NoError(t, err) + assert.Equal(t, zerolog.DebugLevel, r.EffectiveLevel("hotstuff")) + + err = r.Reset("hotstuff") + require.NoError(t, err) + assert.Equal(t, zerolog.WarnLevel, r.EffectiveLevel("hotstuff")) // back to static +} + +// TestLogRegistry_ResetWildcard verifies that Reset with a wildcard removes matching +// overrides and re-resolves affected components. +func TestLogRegistry_ResetWildcard(t *testing.T) { + r, log := testRegistry(t, zerolog.InfoLevel, nil) + r.Logger(log, "hotstuff.voter") + r.Logger(log, "hotstuff.pacemaker") + + err := r.SetLevel("hotstuff.*", zerolog.DebugLevel) + require.NoError(t, err) + assert.Equal(t, zerolog.DebugLevel, r.EffectiveLevel("hotstuff.voter")) + assert.Equal(t, zerolog.DebugLevel, r.EffectiveLevel("hotstuff.pacemaker")) + + err = r.Reset("hotstuff.*") + require.NoError(t, err) + assert.Equal(t, zerolog.InfoLevel, r.EffectiveLevel("hotstuff.voter")) + assert.Equal(t, zerolog.InfoLevel, r.EffectiveLevel("hotstuff.pacemaker")) +} + +// TestLogRegistry_ResetAll verifies that Reset("*") restores all components to static +// config or global default. +func TestLogRegistry_ResetAll(t *testing.T) { + r, log := testRegistry(t, zerolog.InfoLevel, nil) + r.Logger(log, "hotstuff") + r.Logger(log, "network") + + err := r.SetLevel("hotstuff", zerolog.DebugLevel) + require.NoError(t, err) + err = r.SetLevel("network", zerolog.TraceLevel) + require.NoError(t, err) + assert.Equal(t, zerolog.DebugLevel, r.EffectiveLevel("hotstuff")) + assert.Equal(t, zerolog.TraceLevel, r.EffectiveLevel("network")) + + err = r.Reset("*") + require.NoError(t, err) + assert.Equal(t, zerolog.InfoLevel, r.EffectiveLevel("hotstuff")) + assert.Equal(t, zerolog.InfoLevel, r.EffectiveLevel("network")) + assert.Equal(t, zerolog.InfoLevel, zerolog.GlobalLevel()) +} + +// TestLogRegistry_SetDefaultLevel verifies that updating the default re-resolves components +// without explicit overrides and leaves overridden components unchanged. +func TestLogRegistry_SetDefaultLevel(t *testing.T) { + r, log := testRegistry(t, zerolog.InfoLevel, nil) + r.Logger(log, "hotstuff") + r.Logger(log, "network") + + err := r.SetLevel("network", zerolog.WarnLevel) + require.NoError(t, err) + assert.Equal(t, zerolog.WarnLevel, r.EffectiveLevel("network")) + + r.SetDefaultLevel(zerolog.DebugLevel) + assert.Equal(t, zerolog.DebugLevel, r.EffectiveLevel("hotstuff")) // re-resolved + assert.Equal(t, zerolog.WarnLevel, r.EffectiveLevel("network")) // override preserved +} + +// TestLogRegistry_Levels verifies that Levels returns the correct level and source for +// each registered component. +func TestLogRegistry_Levels(t *testing.T) { + r, log := testRegistry(t, zerolog.InfoLevel, map[string]zerolog.Level{ + "hotstuff.voter": zerolog.WarnLevel, + "network.*": zerolog.ErrorLevel, + }) + r.Logger(log, "hotstuff") + r.Logger(log, "hotstuff.voter") + r.Logger(log, "network.p2p") + err := r.SetLevel("hotstuff", zerolog.DebugLevel) + require.NoError(t, err) + + defaultLevel, levels := r.Levels() + assert.Equal(t, zerolog.InfoLevel, defaultLevel) + + assert.Equal(t, zerolog.DebugLevel, levels["hotstuff"].Level) + assert.Equal(t, logging.LevelSourceOverride, levels["hotstuff"].Source) + + assert.Equal(t, zerolog.WarnLevel, levels["hotstuff.voter"].Level) + assert.Equal(t, logging.LevelSourceStatic, levels["hotstuff.voter"].Source) + + assert.Equal(t, zerolog.ErrorLevel, levels["network.p2p"].Level) + assert.Equal(t, logging.LevelSourceStaticWildcard, levels["network.p2p"].Source) +} + +// TestLogRegistry_OutputFiltering_DefaultLevel verifies that at the default level (info), +// debug events produce no output and info events are written. +func TestLogRegistry_OutputFiltering_DefaultLevel(t *testing.T) { + r, log, buf := testRegistryWithBuffer(t, zerolog.InfoLevel) + logger := r.Logger(log, "hotstuff") + + logger.Debug().Msg("debug suppressed") + assert.Empty(t, buf.String(), "debug should produce no output at info level") + + logger.Info().Msg("info visible") + assert.Contains(t, buf.String(), "info visible") +} + +// TestLogRegistry_OutputFiltering_LowerLevel verifies that after SetLevel lowers a +// component to debug, debug events are written to the output. +func TestLogRegistry_OutputFiltering_LowerLevel(t *testing.T) { + r, log, buf := testRegistryWithBuffer(t, zerolog.InfoLevel) + logger := r.Logger(log, "hotstuff") + + logger.Debug().Msg("debug suppressed") + assert.Empty(t, buf.String(), "debug should produce no output at info level") + + err := r.SetLevel("hotstuff", zerolog.DebugLevel) + require.NoError(t, err) + + logger.Debug().Msg("debug now visible") + assert.Contains(t, buf.String(), "debug now visible") +} + +// TestLogRegistry_OutputFiltering_ResetRestoresSuppression verifies that after Reset, +// debug events are suppressed again. +func TestLogRegistry_OutputFiltering_ResetRestoresSuppression(t *testing.T) { + r, log, buf := testRegistryWithBuffer(t, zerolog.InfoLevel) + logger := r.Logger(log, "hotstuff") + + err := r.SetLevel("hotstuff", zerolog.DebugLevel) + require.NoError(t, err) + logger.Debug().Msg("debug visible") + require.Contains(t, buf.String(), "debug visible") + + buf.Reset() + err = r.Reset("hotstuff") + require.NoError(t, err) + + logger.Debug().Msg("debug suppressed again") + assert.Empty(t, buf.String(), "debug should be suppressed after reset") + + logger.Info().Msg("info still visible") + assert.Contains(t, buf.String(), "info still visible") +} + +// TestLogRegistry_OutputFiltering_IndependentComponents verifies that lowering one +// component's level does not cause another component to emit events below its level. +// This tests the key design property: each component has its own componentLevelWriter. +func TestLogRegistry_OutputFiltering_IndependentComponents(t *testing.T) { + r, log, buf := testRegistryWithBuffer(t, zerolog.InfoLevel) + loggerA := r.Logger(log, "component-a") // stays at info + loggerB := r.Logger(log, "component-b") // lowered to debug + + err := r.SetLevel("component-b", zerolog.DebugLevel) + require.NoError(t, err) + // GlobalLevel is now debug to allow B's debug events through — but A's writer + // should still discard them. + + loggerA.Debug().Msg("a-debug") + assert.Empty(t, buf.String(), "component-a should not emit debug despite global level drop") + + loggerB.Debug().Msg("b-debug") + assert.Contains(t, buf.String(), "b-debug", "component-b should emit debug") + + loggerA.Info().Msg("a-info") + assert.Contains(t, buf.String(), "a-info", "component-a should still emit info") +} + +// TestLogRegistry_OutputFiltering_ChildLoggerInheritsLevel verifies that child loggers +// derived from a component logger via With() share the same componentLevelWriter and +// automatically reflect level changes without re-registration. +func TestLogRegistry_OutputFiltering_ChildLoggerInheritsLevel(t *testing.T) { + r, log, buf := testRegistryWithBuffer(t, zerolog.InfoLevel) + parent := r.Logger(log, "hotstuff") + child := parent.With().Str("sub", "voter").Logger() + + // Before: both suppressed at info + parent.Debug().Msg("parent debug suppressed") + child.Debug().Msg("child debug suppressed") + assert.Empty(t, buf.String()) + + // Lower the component level — child should pick it up automatically + err := r.SetLevel("hotstuff", zerolog.DebugLevel) + require.NoError(t, err) + + child.Debug().Msg("child debug visible") + assert.Contains(t, buf.String(), "child debug visible", + "child should inherit level change via shared componentLevelWriter") +} + +// TestLogRegistry_OutputFiltering_WildcardAffectsOutput verifies that a wildcard SetLevel +// affects the actual output of all matching components. +func TestLogRegistry_OutputFiltering_WildcardAffectsOutput(t *testing.T) { + r, log, buf := testRegistryWithBuffer(t, zerolog.InfoLevel) + voter := r.Logger(log, "hotstuff.voter") + pacemaker := r.Logger(log, "hotstuff.pacemaker") + + err := r.SetLevel("hotstuff.*", zerolog.DebugLevel) + require.NoError(t, err) + + voter.Debug().Msg("voter-debug") + pacemaker.Debug().Msg("pacemaker-debug") + + assert.Contains(t, buf.String(), "voter-debug") + assert.Contains(t, buf.String(), "pacemaker-debug") +} + +// TestLogRegistry_Logger_InheritsParentContext verifies that Logger preserves +// all context fields added to the parent logger before the child is registered. +func TestLogRegistry_Logger_InheritsParentContext(t *testing.T) { + r, log, buf := testRegistryWithBuffer(t, zerolog.InfoLevel) + + parent := r.Logger(log, "hotstuff") + parent = parent.With().Str("view", "42").Logger() // add context after registration + + child := r.Logger(parent, "hotstuff.voter") + + child.Info().Msg("child message") + out := buf.String() + assert.Contains(t, out, "child message") + assert.Contains(t, out, `"view":"42"`, "child should inherit parent's context field") +} + +// TestLogRegistry_Logger_IndependentLevelControl verifies that the child registered +// via Logger has its own independently controllable level. +func TestLogRegistry_Logger_IndependentLevelControl(t *testing.T) { + r, log, buf := testRegistryWithBuffer(t, zerolog.InfoLevel) + + parent := r.Logger(log, "hotstuff") + child := r.Logger(parent, "hotstuff.voter") + + // Lower child to debug — parent stays at info + err := r.SetLevel("hotstuff.voter", zerolog.DebugLevel) + require.NoError(t, err) + + parent.Debug().Msg("parent-debug") + assert.Empty(t, buf.String(), "parent should still be at info") + + child.Debug().Msg("child-debug") + assert.Contains(t, buf.String(), "child-debug") +} + +// TestLogRegistry_Logger_ParentLevelDoesNotAffectChild verifies that lowering the +// parent's level does not cause the child to emit events below its own level. +func TestLogRegistry_Logger_ParentLevelDoesNotAffectChild(t *testing.T) { + r, log, buf := testRegistryWithBuffer(t, zerolog.InfoLevel) + + parent := r.Logger(log, "hotstuff") + child := r.Logger(parent, "hotstuff.voter") + + // Lower parent to debug — child stays at info + err := r.SetLevel("hotstuff", zerolog.DebugLevel) + require.NoError(t, err) + + child.Debug().Msg("child-debug") + assert.Empty(t, buf.String(), "child should still be at info") + + parent.Debug().Msg("parent-debug") + assert.Contains(t, buf.String(), "parent-debug") +} + +func TestBestWildcardMatch(t *testing.T) { + tests := []struct { + name string + config map[string]zerolog.Level + id string + expectedLevel zerolog.Level + expectedMatch bool + }{ + { + name: "empty config", + config: map[string]zerolog.Level{}, + id: "hotstuff.voter", + expectedMatch: false, + }, + { + name: "exact pattern ignored", + config: map[string]zerolog.Level{"hotstuff.voter": zerolog.DebugLevel}, + id: "hotstuff.voter", + expectedMatch: false, + }, + { + name: "single match", + config: map[string]zerolog.Level{"hotstuff.*": zerolog.DebugLevel}, + id: "hotstuff.voter", + expectedLevel: zerolog.DebugLevel, + expectedMatch: true, + }, + { + name: "wildcard does not match parent", + config: map[string]zerolog.Level{"hotstuff.*": zerolog.DebugLevel}, + id: "hotstuff", + expectedMatch: false, + }, + { + name: "unrelated wildcard", + config: map[string]zerolog.Level{"network.*": zerolog.DebugLevel}, + id: "hotstuff.voter", + expectedMatch: false, + }, + { + name: "most specific wins", + config: map[string]zerolog.Level{ + "hotstuff.*": zerolog.DebugLevel, + "hotstuff.voter.*": zerolog.WarnLevel, + }, + id: "hotstuff.voter.timer", + expectedLevel: zerolog.WarnLevel, + expectedMatch: true, + }, + { + name: "shallow wildcard matches deep child", + config: map[string]zerolog.Level{"hotstuff.*": zerolog.DebugLevel}, + id: "hotstuff.voter.timer", + expectedLevel: zerolog.DebugLevel, + expectedMatch: true, + }, + { + name: "one of multiple wildcards matches", + config: map[string]zerolog.Level{ + "network.*": zerolog.ErrorLevel, + "hotstuff.*": zerolog.DebugLevel, + }, + id: "hotstuff.voter", + expectedLevel: zerolog.DebugLevel, + expectedMatch: true, + }, + } + + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + level, ok := logging.BestWildcardMatch(tt.config, tt.id) + assert.Equal(t, tt.expectedMatch, ok) + if tt.expectedMatch { + assert.Equal(t, tt.expectedLevel, level) + } + }) + } +} diff --git a/utils/logging/validate.go b/utils/logging/validate.go new file mode 100644 index 00000000000..364cc03f483 --- /dev/null +++ b/utils/logging/validate.go @@ -0,0 +1,56 @@ +package logging + +import ( + "fmt" + "regexp" + "strings" +) + +var ( + // componentIDRegex matches a valid normalized component ID: dot-separated segments + // where each segment starts with an alphanumeric character and contains only + // alphanumeric characters, hyphens, and underscores. + componentIDRegex = regexp.MustCompile(`^[a-z0-9][a-z0-9_-]*(\.[a-z0-9][a-z0-9_-]*)*$`) + + // wildcardPatternRegex matches a valid normalized wildcard pattern: a component ID + // prefix followed by ".*". + wildcardPatternRegex = regexp.MustCompile(`^[a-z0-9][a-z0-9_-]*(\.[a-z0-9][a-z0-9_-]*)*\.\*$`) +) + +// NormalizePattern converts s to lowercase, making component ID and pattern matching +// case-insensitive. Must be applied before [ValidateComponentID] or [ValidatePattern]. +func NormalizePattern(s string) string { + return strings.ToLower(s) +} + +// ValidateComponentID returns an error if s is not a valid component ID. +// s must already be normalized via [NormalizePattern] before calling this function. +// +// A valid component ID consists of dot-separated segments where each segment starts +// with an alphanumeric character and contains only alphanumeric characters, hyphens, +// and underscores. Examples: "hotstuff", "hotstuff.voter", "consensus.vote-aggregator". +// +// Expected error returns during normal operation: +// - error: if s does not match the required format. +func ValidateComponentID(s string) error { + if !componentIDRegex.MatchString(s) { + return fmt.Errorf("invalid component ID %q: must be dot-separated segments of [a-z0-9_-], each starting with [a-z0-9]", s) + } + return nil +} + +// ValidatePattern returns an error if s is not a valid component pattern. +// s must already be normalized via [NormalizePattern] before calling this function. +// +// A valid pattern is either a component ID (e.g. "hotstuff.voter") or a prefix wildcard +// (e.g. "hotstuff.*"). The special reset-all token "*" is not validated by this function +// and must be handled separately by callers. +// +// Expected error returns during normal operation: +// - error: if s does not match the required format. +func ValidatePattern(s string) error { + if componentIDRegex.MatchString(s) || wildcardPatternRegex.MatchString(s) { + return nil + } + return fmt.Errorf("invalid pattern %q: must be a component ID (e.g. \"hotstuff.voter\") or wildcard (e.g. \"hotstuff.*\")", s) +} diff --git a/utils/logging/validate_test.go b/utils/logging/validate_test.go new file mode 100644 index 00000000000..35997c1c2c3 --- /dev/null +++ b/utils/logging/validate_test.go @@ -0,0 +1,135 @@ +package logging_test + +import ( + "testing" + + "github.com/rs/zerolog" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + + "github.com/onflow/flow-go/utils/logging" +) + +func TestNormalizePattern(t *testing.T) { + assert.Equal(t, "hotstuff", logging.NormalizePattern("HotStuff")) + assert.Equal(t, "hotstuff.voter", logging.NormalizePattern("Hotstuff.Voter")) + assert.Equal(t, "network.*", logging.NormalizePattern("NETWORK.*")) + assert.Equal(t, "already-lower", logging.NormalizePattern("already-lower")) +} + +func TestValidateComponentID(t *testing.T) { + valid := []string{ + "hotstuff", + "hotstuff.voter", + "consensus.vote-aggregator", + "execution.state_sync", + "network.p2p.gossipsub", + "a", + "a1", + "node123", + } + for _, id := range valid { + t.Run(id, func(t *testing.T) { + require.NoError(t, logging.ValidateComponentID(id)) + }) + } + + invalid := []string{ + "", + "Hotstuff", // uppercase rejected (must normalize first) + "hotstuff.", // trailing dot + ".hotstuff", // leading dot + "hotstuff..voter", // double dot + "hotstuff.*", // wildcard is not a component ID + "*", // reset-all token + "-hotstuff", // segment starting with hyphen + "hotstuff voter", // space + } + for _, id := range invalid { + t.Run(id, func(t *testing.T) { + require.Error(t, logging.ValidateComponentID(id)) + }) + } +} + +func TestValidatePattern(t *testing.T) { + valid := []string{ + "hotstuff", + "hotstuff.voter", + "hotstuff.*", + "hotstuff.voter.*", + "network.*", + "consensus.vote-aggregator", + "execution.state_sync.*", + } + for _, p := range valid { + t.Run(p, func(t *testing.T) { + require.NoError(t, logging.ValidatePattern(p)) + }) + } + + invalid := []string{ + "", + "*", // reset-all token, not a pattern + "hotstuff.**", // double wildcard + "hotstuff.*.voter", // wildcard in the middle + "*.hotstuff", // wildcard at the beginning + "hotstuff*", // wildcard without dot + "HotStuff", // uppercase rejected (must normalize first) + "-hotstuff", // segment starting with hyphen + "hotstuff.", // trailing dot without wildcard + } + for _, p := range invalid { + t.Run(p, func(t *testing.T) { + require.Error(t, logging.ValidatePattern(p)) + }) + } +} + +// TestLogRegistry_NormalizesComponentID verifies that Logger() normalizes the ID to +// lowercase, such that mixed-case and lowercase refer to the same registration. +func TestLogRegistry_NormalizesComponentID(t *testing.T) { + r, log := testRegistry(t, zerolog.InfoLevel, nil) + r.Logger(log, "HotStuff") // registered as "hotstuff" + + // Prove they are the same registration: changing via the lowercase key is + // reflected in the mixed-case lookup, and attempting to re-register panics. + err := r.SetLevel("hotstuff", zerolog.DebugLevel) + require.NoError(t, err) + assert.Equal(t, zerolog.DebugLevel, r.EffectiveLevel("HotStuff"), "mixed-case lookup should see the level change") + + require.Panics(t, func() { r.Logger(log, "hotstuff") }, "re-registering the normalized form should panic") +} + +// TestLogRegistry_NormalizesSetLevel verifies that SetLevel normalizes the pattern. +func TestLogRegistry_NormalizesSetLevel(t *testing.T) { + r, log := testRegistry(t, zerolog.InfoLevel, nil) + r.Logger(log, "hotstuff.voter") + + err := r.SetLevel("Hotstuff.Voter", zerolog.DebugLevel) + require.NoError(t, err) + assert.Equal(t, zerolog.DebugLevel, r.EffectiveLevel("hotstuff.voter")) +} + +// TestLogRegistry_PanicsOnInvalidComponentID verifies that Logger() panics for invalid IDs. +func TestLogRegistry_PanicsOnInvalidComponentID(t *testing.T) { + r, log := testRegistry(t, zerolog.InfoLevel, nil) + require.Panics(t, func() { r.Logger(log, "invalid id with spaces") }) + require.Panics(t, func() { r.Logger(log, ".leading-dot") }) + require.Panics(t, func() { r.Logger(log, "trailing-dot.") }) +} + +// TestParseComponentLogLevels_NormalizesAndValidatesPatterns verifies that parsing +// normalizes component names and rejects invalid patterns. +func TestParseComponentLogLevels_NormalizesAndValidatesPatterns(t *testing.T) { + // Mixed case is normalized + result, err := logging.ParseComponentLogLevels("HotStuff:debug") + require.NoError(t, err) + assert.Equal(t, zerolog.DebugLevel, result["hotstuff"]) + _, hasOriginal := result["HotStuff"] + assert.False(t, hasOriginal, "original case key should not be present") + + // Invalid pattern is rejected + _, err = logging.ParseComponentLogLevels("invalid id:debug") + require.Error(t, err) +}