From f719e96ea3c7458ab75765c561d5e9351b936778 Mon Sep 17 00:00:00 2001 From: DmitriyLewen Date: Thu, 22 Aug 2024 14:10:08 +0600 Subject: [PATCH 1/6] fix: init logger before parse flags --- pkg/commands/app.go | 6 ++++++ 1 file changed, 6 insertions(+) diff --git a/pkg/commands/app.go b/pkg/commands/app.go index a3fb6df353d9..280d1fa3cc2e 100644 --- a/pkg/commands/app.go +++ b/pkg/commands/app.go @@ -65,6 +65,12 @@ Use "{{.CommandPath}} [command] --help" for more information about a command.{{e // NewApp is the factory method to return Trivy CLI func NewApp() *cobra.Command { cobra.EnableTraverseRunHooks = true // To execute persistent pre-run hooks from all parents. + + // Initialize the logger for `flag` and `app` packages. + // To display logs from these packages in Trivy format. + // We will set the `debug` and `disable` format after parsing the `--debug` and `--quiet` flags. + log.InitLogger(false, false) + globalFlags := flag.NewGlobalFlagGroup() rootCmd := NewRootCommand(globalFlags) rootCmd.AddGroup( From 6ad109849085aab8cfb1ae04aa9a4b4315d59911 Mon Sep 17 00:00:00 2001 From: DmitriyLewen Date: Thu, 22 Aug 2024 16:15:46 +0600 Subject: [PATCH 2/6] feat: add deferredLogger --- pkg/commands/app.go | 14 ++++-------- pkg/flag/options.go | 10 ++++---- pkg/log/deferred.go | 56 +++++++++++++++++++++++++++++++++++++++++++++ 3 files changed, 66 insertions(+), 14 deletions(-) create mode 100644 pkg/log/deferred.go diff --git a/pkg/commands/app.go b/pkg/commands/app.go index 280d1fa3cc2e..1728efdb8f04 100644 --- a/pkg/commands/app.go +++ b/pkg/commands/app.go @@ -65,12 +65,6 @@ Use "{{.CommandPath}} [command] --help" for more information about a command.{{e // NewApp is the factory method to return Trivy CLI func NewApp() *cobra.Command { cobra.EnableTraverseRunHooks = true // To execute persistent pre-run hooks from all parents. - - // Initialize the logger for `flag` and `app` packages. - // To display logs from these packages in Trivy format. - // We will set the `debug` and `disable` format after parsing the `--debug` and `--quiet` flags. - log.InitLogger(false, false) - globalFlags := flag.NewGlobalFlagGroup() rootCmd := NewRootCommand(globalFlags) rootCmd.AddGroup( @@ -134,7 +128,7 @@ func loadPluginCommands() []*cobra.Command { var commands []*cobra.Command plugins, err := plugin.NewManager().LoadAll(ctx) if err != nil { - log.DebugContext(ctx, "No plugins loaded") + log.DeferredLogger.Debug("No plugins loaded") return nil } for _, p := range plugins { @@ -166,13 +160,13 @@ func initConfig(configFile string, pathChanged bool) error { if err := viper.ReadInConfig(); err != nil { if errors.Is(err, os.ErrNotExist) { if !pathChanged { - log.Debugf("Default config file %q not found, using built in values", log.FilePath(configFile)) + log.DeferredLogger.Debug(fmt.Sprintf("Default config file %q not found, using built in values", log.FilePath(configFile))) return nil } } return xerrors.Errorf("config file %q loading error: %s", configFile, err) } - log.Info("Loaded", log.FilePath(configFile)) + log.DeferredLogger.Info("Loaded", log.FilePath(configFile)) return nil } @@ -222,6 +216,8 @@ func NewRootCommand(globalFlags *flag.GlobalFlagGroup) *cobra.Command { // Initialize logger log.InitLogger(globalOptions.Debug, globalOptions.Quiet) + // Print log messages waiting for logger initialization + log.DeferredLogger.PrintLogs() return nil }, diff --git a/pkg/flag/options.go b/pkg/flag/options.go index e00aa4cfa922..eeb848351bcd 100644 --- a/pkg/flag/options.go +++ b/pkg/flag/options.go @@ -119,10 +119,10 @@ func (f *Flag[T]) Parse() error { } if f.Deprecated != "" && f.isSet() { - log.Warnf(`"--%s" is deprecated. %s`, f.Name, f.Deprecated) + log.DeferredLogger.Warn(fmt.Sprintf(`"--%s" is deprecated. %s`, f.Name, f.Deprecated)) } if f.Removed != "" && f.isSet() { - log.Errorf(`"--%s" was removed. %s`, f.Name, f.Removed) + log.DeferredLogger.Error(fmt.Sprintf(`"--%s" was removed. %s`, f.Name, f.Removed)) return xerrors.Errorf(`removed flag ("--%s")`, f.Name) } @@ -140,7 +140,7 @@ func (f *Flag[T]) parse() any { } v = viper.Get(alias.ConfigName) if v != nil { - log.Warnf("'%s' in config file is deprecated. Use '%s' instead.", alias.ConfigName, f.ConfigName) + log.DeferredLogger.Warn(fmt.Sprintf("'%s' in config file is deprecated. Use '%s' instead.", alias.ConfigName, f.ConfigName)) return v } } @@ -307,7 +307,7 @@ func (f *Flag[T]) BindEnv() error { } if alias.Deprecated { if _, ok := os.LookupEnv(envAlias); ok { - log.Warnf("'%s' is deprecated. Use '%s' instead.", envAlias, envName) + log.DeferredLogger.Warn(fmt.Sprintf("'%s' is deprecated. Use '%s' instead.", envAlias, envName)) } } } @@ -848,7 +848,7 @@ func (a flagAliases) NormalizeFunc() func(*pflag.FlagSet, string) pflag.Normaliz if alias.deprecated { // NormalizeFunc is called several times alias.once.Do(func() { - log.Warnf("'--%s' is deprecated. Use '--%s' instead.", name, alias.formalName) + log.DeferredLogger.Warn(fmt.Sprintf("'--%s' is deprecated. Use '--%s' instead.", name, alias.formalName)) }) } name = alias.formalName diff --git a/pkg/log/deferred.go b/pkg/log/deferred.go new file mode 100644 index 000000000000..fb455ae02beb --- /dev/null +++ b/pkg/log/deferred.go @@ -0,0 +1,56 @@ +package log + +// DeferredLogger are needed to save logs and print them after calling `PrintLogs()` command. +// for example, this may be necessary when the logger is not yet initialized, but messages need to be transmitted +// in this case, the messages are saved and printed after the logger is initialized +var DeferredLogger deferredLogger + +type deferredLogger struct { + deferredLogs []deferredLog +} + +type deferredLog struct { + logFunc func(format string, args ...any) + message string + args []any +} + +func (d *deferredLogger) Debug(message string, args ...any) { + d.deferredLogs = append(d.deferredLogs, deferredLog{ + logFunc: Debug, + message: message, + args: args, + }) +} + +func (d *deferredLogger) Info(message string, args ...any) { + d.deferredLogs = append(d.deferredLogs, deferredLog{ + logFunc: Info, + message: message, + args: args, + }) +} + +func (d *deferredLogger) Warn(message string, args ...any) { + d.deferredLogs = append(d.deferredLogs, deferredLog{ + logFunc: Warn, + message: message, + args: args, + }) +} + +func (d *deferredLogger) Error(message string, args ...any) { + d.deferredLogs = append(d.deferredLogs, deferredLog{ + logFunc: Error, + message: message, + args: args, + }) +} + +func (d *deferredLogger) PrintLogs() { + for _, l := range d.deferredLogs { + l.logFunc(l.message, l.args...) + } + // Clear deferredLogs + d.deferredLogs = nil +} From b4f276c9c99cff0d47a09bbbeedc45781235940c Mon Sep 17 00:00:00 2001 From: DmitriyLewen Date: Mon, 26 Aug 2024 17:57:13 +0600 Subject: [PATCH 3/6] refactor: use `DeferredLogger` for `RegisterRegoRules` func --- pkg/iac/rego/embed.go | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/pkg/iac/rego/embed.go b/pkg/iac/rego/embed.go index e582508a396b..c88ec9fcdf46 100644 --- a/pkg/iac/rego/embed.go +++ b/pkg/iac/rego/embed.go @@ -54,12 +54,12 @@ func RegisterRegoRules(modules map[string]*ast.Module) { for _, module := range modules { metadata, err := retriever.RetrieveMetadata(ctx, module) if err != nil { - log.Warn("Failed to retrieve metadata", log.String("avdid", metadata.AVDID), log.Err(err)) + log.DeferredLogger.Warn("Failed to retrieve metadata", log.String("avdid", metadata.AVDID), log.Err(err)) continue } if metadata.AVDID == "" { - log.Warn("Check ID is empty", log.FilePath(module.Package.Location.File)) + log.DeferredLogger.Warn("Check ID is empty", log.FilePath(module.Package.Location.File)) continue } @@ -73,7 +73,7 @@ func RegisterRegoRules(modules map[string]*ast.Module) { for _, check := range rules.GetRegistered() { if !check.Deprecated && check.CanCheck() { if _, exists := regoCheckIDs[check.AVDID]; exists { - log.Warn("Ignore duplicate Go check", log.String("avdid", check.AVDID)) + log.DeferredLogger.Warn("Ignore duplicate Go check", log.String("avdid", check.AVDID)) rules.Deregister(check) } } From c89c05fb27d9466442a503873db18b7b5f17016e Mon Sep 17 00:00:00 2001 From: knqyf263 Date: Fri, 30 Aug 2024 18:11:48 +0400 Subject: [PATCH 4/6] revert Signed-off-by: knqyf263 --- pkg/commands/app.go | 8 +++----- pkg/flag/options.go | 10 +++++----- pkg/iac/rego/embed.go | 6 +++--- 3 files changed, 11 insertions(+), 13 deletions(-) diff --git a/pkg/commands/app.go b/pkg/commands/app.go index 1728efdb8f04..ded04ef39774 100644 --- a/pkg/commands/app.go +++ b/pkg/commands/app.go @@ -128,7 +128,7 @@ func loadPluginCommands() []*cobra.Command { var commands []*cobra.Command plugins, err := plugin.NewManager().LoadAll(ctx) if err != nil { - log.DeferredLogger.Debug("No plugins loaded") + log.Debug("No plugins loaded") return nil } for _, p := range plugins { @@ -160,13 +160,13 @@ func initConfig(configFile string, pathChanged bool) error { if err := viper.ReadInConfig(); err != nil { if errors.Is(err, os.ErrNotExist) { if !pathChanged { - log.DeferredLogger.Debug(fmt.Sprintf("Default config file %q not found, using built in values", log.FilePath(configFile))) + log.Debug(fmt.Sprintf("Default config file %q not found, using built in values", log.FilePath(configFile))) return nil } } return xerrors.Errorf("config file %q loading error: %s", configFile, err) } - log.DeferredLogger.Info("Loaded", log.FilePath(configFile)) + log.Info("Loaded", log.FilePath(configFile)) return nil } @@ -216,8 +216,6 @@ func NewRootCommand(globalFlags *flag.GlobalFlagGroup) *cobra.Command { // Initialize logger log.InitLogger(globalOptions.Debug, globalOptions.Quiet) - // Print log messages waiting for logger initialization - log.DeferredLogger.PrintLogs() return nil }, diff --git a/pkg/flag/options.go b/pkg/flag/options.go index eeb848351bcd..2038af2cb90d 100644 --- a/pkg/flag/options.go +++ b/pkg/flag/options.go @@ -119,10 +119,10 @@ func (f *Flag[T]) Parse() error { } if f.Deprecated != "" && f.isSet() { - log.DeferredLogger.Warn(fmt.Sprintf(`"--%s" is deprecated. %s`, f.Name, f.Deprecated)) + log.Warn(fmt.Sprintf(`"--%s" is deprecated. %s`, f.Name, f.Deprecated)) } if f.Removed != "" && f.isSet() { - log.DeferredLogger.Error(fmt.Sprintf(`"--%s" was removed. %s`, f.Name, f.Removed)) + log.Error(fmt.Sprintf(`"--%s" was removed. %s`, f.Name, f.Removed)) return xerrors.Errorf(`removed flag ("--%s")`, f.Name) } @@ -140,7 +140,7 @@ func (f *Flag[T]) parse() any { } v = viper.Get(alias.ConfigName) if v != nil { - log.DeferredLogger.Warn(fmt.Sprintf("'%s' in config file is deprecated. Use '%s' instead.", alias.ConfigName, f.ConfigName)) + log.Warn(fmt.Sprintf("'%s' in config file is deprecated. Use '%s' instead.", alias.ConfigName, f.ConfigName)) return v } } @@ -307,7 +307,7 @@ func (f *Flag[T]) BindEnv() error { } if alias.Deprecated { if _, ok := os.LookupEnv(envAlias); ok { - log.DeferredLogger.Warn(fmt.Sprintf("'%s' is deprecated. Use '%s' instead.", envAlias, envName)) + log.Warn(fmt.Sprintf("'%s' is deprecated. Use '%s' instead.", envAlias, envName)) } } } @@ -848,7 +848,7 @@ func (a flagAliases) NormalizeFunc() func(*pflag.FlagSet, string) pflag.Normaliz if alias.deprecated { // NormalizeFunc is called several times alias.once.Do(func() { - log.DeferredLogger.Warn(fmt.Sprintf("'--%s' is deprecated. Use '--%s' instead.", name, alias.formalName)) + log.Warn(fmt.Sprintf("'--%s' is deprecated. Use '--%s' instead.", name, alias.formalName)) }) } name = alias.formalName diff --git a/pkg/iac/rego/embed.go b/pkg/iac/rego/embed.go index c88ec9fcdf46..e582508a396b 100644 --- a/pkg/iac/rego/embed.go +++ b/pkg/iac/rego/embed.go @@ -54,12 +54,12 @@ func RegisterRegoRules(modules map[string]*ast.Module) { for _, module := range modules { metadata, err := retriever.RetrieveMetadata(ctx, module) if err != nil { - log.DeferredLogger.Warn("Failed to retrieve metadata", log.String("avdid", metadata.AVDID), log.Err(err)) + log.Warn("Failed to retrieve metadata", log.String("avdid", metadata.AVDID), log.Err(err)) continue } if metadata.AVDID == "" { - log.DeferredLogger.Warn("Check ID is empty", log.FilePath(module.Package.Location.File)) + log.Warn("Check ID is empty", log.FilePath(module.Package.Location.File)) continue } @@ -73,7 +73,7 @@ func RegisterRegoRules(modules map[string]*ast.Module) { for _, check := range rules.GetRegistered() { if !check.Deprecated && check.CanCheck() { if _, exists := regoCheckIDs[check.AVDID]; exists { - log.DeferredLogger.Warn("Ignore duplicate Go check", log.String("avdid", check.AVDID)) + log.Warn("Ignore duplicate Go check", log.String("avdid", check.AVDID)) rules.Deregister(check) } } From b731f780a0208b4ac32a06cdccfd6979cf5482b1 Mon Sep 17 00:00:00 2001 From: knqyf263 Date: Fri, 30 Aug 2024 18:12:34 +0400 Subject: [PATCH 5/6] refactor: add DeferredHandler Signed-off-by: knqyf263 --- pkg/log/deferred.go | 82 ++++++++++++++++++++++++--------------------- pkg/log/logger.go | 11 ++++-- 2 files changed, 53 insertions(+), 40 deletions(-) diff --git a/pkg/log/deferred.go b/pkg/log/deferred.go index fb455ae02beb..9fbf81652f4d 100644 --- a/pkg/log/deferred.go +++ b/pkg/log/deferred.go @@ -1,56 +1,62 @@ package log -// DeferredLogger are needed to save logs and print them after calling `PrintLogs()` command. -// for example, this may be necessary when the logger is not yet initialized, but messages need to be transmitted -// in this case, the messages are saved and printed after the logger is initialized -var DeferredLogger deferredLogger +import ( + "context" + "log/slog" + "slices" +) + +func init() { + // Set the default logger so that logs are buffered until the logger is initialized. + slog.SetDefault(New(&DeferredHandler{records: new([]deferredRecord)})) +} + +// DeferredHandler is needed to save logs and print them after calling `PrintLogs()` command. +// For example, this may be necessary when the logger is not yet initialized, but messages need to be transmitted. +// In this case, the messages are saved and printed when the logger is initialized. +type DeferredHandler struct { + attrs []slog.Attr -type deferredLogger struct { - deferredLogs []deferredLog + // Shared with all instances of the handler. + // NOTE: non-thread safe + records *[]deferredRecord } -type deferredLog struct { - logFunc func(format string, args ...any) - message string - args []any +type deferredRecord struct { + ctx context.Context + slog.Record } -func (d *deferredLogger) Debug(message string, args ...any) { - d.deferredLogs = append(d.deferredLogs, deferredLog{ - logFunc: Debug, - message: message, - args: args, - }) +func (*DeferredHandler) Enabled(context.Context, slog.Level) bool { + return true } -func (d *deferredLogger) Info(message string, args ...any) { - d.deferredLogs = append(d.deferredLogs, deferredLog{ - logFunc: Info, - message: message, - args: args, +func (d *DeferredHandler) Handle(ctx context.Context, record slog.Record) error { + record.AddAttrs(d.attrs...) + *d.records = append(*d.records, deferredRecord{ + ctx: ctx, + Record: record, }) + return nil } -func (d *deferredLogger) Warn(message string, args ...any) { - d.deferredLogs = append(d.deferredLogs, deferredLog{ - logFunc: Warn, - message: message, - args: args, - }) +func (d *DeferredHandler) WithAttrs(attrs []slog.Attr) slog.Handler { + h := *d + h.attrs = slices.Clip(d.attrs) + h.attrs = append(h.attrs, attrs...) + return &h } -func (d *deferredLogger) Error(message string, args ...any) { - d.deferredLogs = append(d.deferredLogs, deferredLog{ - logFunc: Error, - message: message, - args: args, - }) +func (*DeferredHandler) WithGroup(_ string) slog.Handler { + panic("WithGroup is not implemented") } -func (d *deferredLogger) PrintLogs() { - for _, l := range d.deferredLogs { - l.logFunc(l.message, l.args...) +func (d *DeferredHandler) Flush(h slog.Handler) { + for _, record := range *d.records { + if !h.Enabled(record.ctx, record.Level) { + continue + } + _ = h.Handle(record.ctx, record.Record) } - // Clear deferredLogs - d.deferredLogs = nil + d.records = nil } diff --git a/pkg/log/logger.go b/pkg/log/logger.go index 73c4231fd4af..7337c1438818 100644 --- a/pkg/log/logger.go +++ b/pkg/log/logger.go @@ -33,11 +33,18 @@ func New(h slog.Handler) *Logger { return slog.New(h) } -// InitLogger initialize the logger variable +// InitLogger initializes the logger variable and flushes the buffered logs. func InitLogger(debug, disable bool) { level := lo.Ternary(debug, slog.LevelDebug, slog.LevelInfo) out := lo.Ternary(disable, io.Discard, io.Writer(os.Stderr)) - slog.SetDefault(New(NewHandler(out, &Options{Level: level}))) + h := NewHandler(out, &Options{Level: level}) + + // Flush the buffered logs if needed. + if d, ok := slog.Default().Handler().(*DeferredHandler); ok { + d.Flush(h) + } + + slog.SetDefault(New(h)) } var ( From c1fb344bfcd98664f5f6904a9c0cfeb11931f27f Mon Sep 17 00:00:00 2001 From: knqyf263 Date: Fri, 30 Aug 2024 18:19:23 +0400 Subject: [PATCH 6/6] revert Signed-off-by: knqyf263 --- pkg/commands/app.go | 4 ++-- pkg/flag/options.go | 10 +++++----- pkg/log/logger.go | 2 +- 3 files changed, 8 insertions(+), 8 deletions(-) diff --git a/pkg/commands/app.go b/pkg/commands/app.go index ded04ef39774..a3fb6df353d9 100644 --- a/pkg/commands/app.go +++ b/pkg/commands/app.go @@ -128,7 +128,7 @@ func loadPluginCommands() []*cobra.Command { var commands []*cobra.Command plugins, err := plugin.NewManager().LoadAll(ctx) if err != nil { - log.Debug("No plugins loaded") + log.DebugContext(ctx, "No plugins loaded") return nil } for _, p := range plugins { @@ -160,7 +160,7 @@ func initConfig(configFile string, pathChanged bool) error { if err := viper.ReadInConfig(); err != nil { if errors.Is(err, os.ErrNotExist) { if !pathChanged { - log.Debug(fmt.Sprintf("Default config file %q not found, using built in values", log.FilePath(configFile))) + log.Debugf("Default config file %q not found, using built in values", log.FilePath(configFile)) return nil } } diff --git a/pkg/flag/options.go b/pkg/flag/options.go index 2038af2cb90d..e00aa4cfa922 100644 --- a/pkg/flag/options.go +++ b/pkg/flag/options.go @@ -119,10 +119,10 @@ func (f *Flag[T]) Parse() error { } if f.Deprecated != "" && f.isSet() { - log.Warn(fmt.Sprintf(`"--%s" is deprecated. %s`, f.Name, f.Deprecated)) + log.Warnf(`"--%s" is deprecated. %s`, f.Name, f.Deprecated) } if f.Removed != "" && f.isSet() { - log.Error(fmt.Sprintf(`"--%s" was removed. %s`, f.Name, f.Removed)) + log.Errorf(`"--%s" was removed. %s`, f.Name, f.Removed) return xerrors.Errorf(`removed flag ("--%s")`, f.Name) } @@ -140,7 +140,7 @@ func (f *Flag[T]) parse() any { } v = viper.Get(alias.ConfigName) if v != nil { - log.Warn(fmt.Sprintf("'%s' in config file is deprecated. Use '%s' instead.", alias.ConfigName, f.ConfigName)) + log.Warnf("'%s' in config file is deprecated. Use '%s' instead.", alias.ConfigName, f.ConfigName) return v } } @@ -307,7 +307,7 @@ func (f *Flag[T]) BindEnv() error { } if alias.Deprecated { if _, ok := os.LookupEnv(envAlias); ok { - log.Warn(fmt.Sprintf("'%s' is deprecated. Use '%s' instead.", envAlias, envName)) + log.Warnf("'%s' is deprecated. Use '%s' instead.", envAlias, envName) } } } @@ -848,7 +848,7 @@ func (a flagAliases) NormalizeFunc() func(*pflag.FlagSet, string) pflag.Normaliz if alias.deprecated { // NormalizeFunc is called several times alias.once.Do(func() { - log.Warn(fmt.Sprintf("'--%s' is deprecated. Use '--%s' instead.", name, alias.formalName)) + log.Warnf("'--%s' is deprecated. Use '--%s' instead.", name, alias.formalName) }) } name = alias.formalName diff --git a/pkg/log/logger.go b/pkg/log/logger.go index 7337c1438818..ac629d211157 100644 --- a/pkg/log/logger.go +++ b/pkg/log/logger.go @@ -33,7 +33,7 @@ func New(h slog.Handler) *Logger { return slog.New(h) } -// InitLogger initializes the logger variable and flushes the buffered logs. +// InitLogger initializes the logger variable and flushes the buffered logs if needed. func InitLogger(debug, disable bool) { level := lo.Ternary(debug, slog.LevelDebug, slog.LevelInfo) out := lo.Ternary(disable, io.Discard, io.Writer(os.Stderr))