diff --git a/arbiter.go b/arbiter.go index 51b30db..768bf23 100644 --- a/arbiter.go +++ b/arbiter.go @@ -12,7 +12,6 @@ import ( "time" "github.com/go-logr/logr" - abtrlog "github.com/maansaake/arbiter/internal/log" "github.com/maansaake/arbiter/pkg/module" "github.com/maansaake/arbiter/pkg/report" "github.com/maansaake/arbiter/pkg/report/collection" @@ -25,6 +24,7 @@ import ( "github.com/spf13/cobra" "github.com/spf13/pflag" "github.com/trebent/envparser" + "github.com/trebent/zerologr" ) type ( @@ -38,6 +38,8 @@ type ( reportPath string // interactive is set when an interactive TUI reporting is used. interactive bool + // logger is used for info-level logging. + logger logr.Logger // errorLogger is the logger used for error logs by the reporter. errorLogger logr.Logger } @@ -51,27 +53,26 @@ type ( } ) +const ( + defaultInfoLogPath = "info.log" + defaultErrorLogPath = "error.log" + defaultDuration = time.Minute * 5 + defaultReportPath = "report.yaml" + defaultInteractive = false +) + // defaultOpts sets zero-value fields to their defaults. func (o *Opts) defaultOpts() { if o.ErrorLogPath == "" { - o.InfoLogPath = abtrlog.DefaultErrorLogPath + o.ErrorLogPath = defaultErrorLogPath } - if o.ErrorLogPath == "" { - o.InfoLogPath = abtrlog.DefaultInfoLogPath + if o.InfoLogPath == "" { + o.InfoLogPath = defaultInfoLogPath } } -const ( - defaultDuration = time.Minute * 5 - defaultReportPath = "report.yaml" - defaultInteractive = false -) - var ( - // logger is the package logger for the arbiter package. - logger logr.Logger //nolint:gochecknoglobals // package-level state for arbiter - // rootCmd holds the cobra root command for Usage access. //nolint:gochecknoglobals // package-level command for Usage access rootCmd *cobra.Command @@ -123,21 +124,17 @@ func Run(modules module.Modules, opts *Opts) error { SilenceUsage: true, } - errorLogger, err := abtrlog.Setup(&abtrlog.Opts{ - Verbosity: logVerbosity.Value(), - ErrorLogPath: opts.ErrorLogPath, - InfoLogPath: opts.InfoLogPath, - }) + infoLogger, errorLogger, err := setupLoggers(opts, logVerbosity.Value()) if err != nil { return fmt.Errorf("failed to build loggers: %w", err) } - logger = abtrlog.GetLogger() abtr := &abtr{ opts: opts, duration: defaultDuration, reportPath: defaultReportPath, interactive: defaultInteractive, + logger: infoLogger, errorLogger: errorLogger, } @@ -240,18 +237,14 @@ func (a *abtr) buildRunnerFlagSet() *pflag.FlagSet { return runnerFlagSet } -// run runs the input modules and starts generating traffic. Creates a traffic -// model based on the modules opertation settings. Aborts on SIGINT, SIGTERM -// or when the test duration runs out. Will immediately exit if any module -// returns an error from its call to Run(). func (a *abtr) run(metadata module.Metadata) error { - logger.Info("Starting modules") + a.logger.Info("Starting modules") - if err := startModules(metadata); err != nil { - logger.Error(err, "Start failure") + if err := a.startModules(metadata); err != nil { + a.logger.Error(err, "Start failure") return err } - logger.Info("All modules started") + a.logger.Info("All modules started") // Start signal interceptor for SIGINT and SIGTERM signalCtx, signalCancel := signal.NotifyContext(context.Background(), syscall.SIGINT, syscall.SIGTERM) @@ -265,7 +258,7 @@ func (a *abtr) run(metadata module.Metadata) error { // Traffic context with a timeout of the test's >>> duration <<< timeoutCtx, timeoutCancel := context.WithTimeout(signalCtx, a.duration) defer timeoutCancel() - logger.Info("Traffic will run for: " + a.duration.String()) + a.logger.Info("Traffic will run for: " + a.duration.String()) // The reporter runs in its own context to allow reporting to finalize separately from traffic and module // shutdown. @@ -274,26 +267,26 @@ func (a *abtr) run(metadata module.Metadata) error { reporter.Start(reporterCtx) sched := traffic.New(&traffic.Opts{ - Logger: logger, + Logger: a.logger, WorkerLimit: workerLimit.Value(), }) // Run traffic. if err := sched.Run(timeoutCtx, metadata, reporter); err != nil { reporter.ReportError(err) // Report is done in case of early traffic failure, to highlight issues in the TUI. - logger.Error(err, "Failed to start traffic") + a.logger.Error(err, "Failed to start traffic") return err } - logger.Info("Awaiting completion (SIGINT/SIGTERM or duration timeout)") + a.logger.Info("Awaiting completion (SIGINT/SIGTERM or duration timeout)") select { case <-signalCtx.Done(): - logger.Info("Got stop signal") + a.logger.Info("Got stop signal") // no need to call timeoutCancel() here since the traffic context is a child of the signal context, // so will be cancelled automatically. // timeoutCancel() case <-timeoutCtx.Done(): - logger.Info("Deadline exceeded") + a.logger.Info("Deadline exceeded") // Needed to terminate the parent context, in case other's are reliant on it. signalCancel() } @@ -302,35 +295,35 @@ func (a *abtr) run(metadata module.Metadata) error { // to be returned at the end of the function. var stopErr error if stopErr = sched.Stop(); stopErr != nil { - logger.Error(stopErr, "Error when stopping traffic") + a.logger.Error(stopErr, "Error when stopping traffic") stopErr = fmt.Errorf("%w: traffic stop: %w", ErrStopping, stopErr) } // Now that traffic has been stopped, we can stop the reporter to allow it to finalise the report. reporterCancel() - logger.Info("Stopping modules") + a.logger.Info("Stopping modules") for _, m := range metadata { if moduleStopErr := m.Stop(); moduleStopErr != nil { - logger.Error(moduleStopErr, "Module stop reported an error", "module", m.Name()) + a.logger.Error(moduleStopErr, "Module stop reported an error", "module", m.Name()) stopErr = errors.Join(stopErr, fmt.Errorf("module %s stop: %w", m.Name(), moduleStopErr)) } } - logger.Info("Finalising report") + a.logger.Info("Finalising report") reporterStopErr := reporter.Finalise() if reporterStopErr != nil { - logger.Error(reporterStopErr, "Error when finalising report") + a.logger.Error(reporterStopErr, "Error when finalising report") stopErr = errors.Join(stopErr, fmt.Errorf("reporter stop: %w", reporterStopErr)) } return stopErr } -// Starts the input modules and logs any errors. -func startModules(meta []*module.Meta) error { +// startModules starts the input modules and logs any errors. +func (a *abtr) startModules(meta []*module.Meta) error { for _, m := range meta { - logger.Info("Starting", "module", m.Name()) + a.logger.Info("Starting", "module", m.Name()) if err := m.Run(); err != nil { return fmt.Errorf("failed to start module %s: %w", m.Name(), err) } @@ -339,7 +332,7 @@ func startModules(meta []*module.Meta) error { return nil } -// Creates the reporter(s). In interactive mode a collection reporter is +// setupReporter creates the reporter(s). In interactive mode a collection reporter is // returned that fans out to both a YAML reporter and the live TUI reporter. // trafficCancel is called by the interactive reporter when the user requests an early // stop (e.g. Ctrl-C inside the TUI), triggering the same shutdown path as @@ -352,6 +345,7 @@ func (a *abtr) setupReporter( ) report.Reporter { yamlR := yamlreport.New(&yamlreport.Opts{ Path: a.reportPath, + Logger: a.logger, ErrorLogger: a.errorLogger, }) @@ -369,3 +363,38 @@ func (a *abtr) setupReporter( return yamlR } + +// setupLoggers initialises the info and error loggers from the provided options. +// It returns the info logger, the error logger, and any error encountered. +func setupLoggers(opts *Opts, verbosity int) (logr.Logger, logr.Logger, error) { + errorFile, err := os.Create(opts.ErrorLogPath) + if err != nil { + return logr.Logger{}, logr.Logger{}, err + } + + var infoLogger logr.Logger + if opts.InfoLogPath == "" { + infoLogger = logr.Discard() + } else { + infoFile, err := os.Create(opts.InfoLogPath) //nolint:govet // shad + if err != nil { + return logr.Logger{}, logr.Logger{}, err + } + + infoLogger = zerologr.New(&zerologr.Opts{ + Output: infoFile, + Console: true, + Caller: true, + V: verbosity, + }).WithName("abtr") + } + + errorLogger := zerologr.New(&zerologr.Opts{ + Output: errorFile, + Console: true, + Caller: false, + V: verbosity, + }) + + return infoLogger, errorLogger, nil +} diff --git a/internal/log/log.go b/internal/log/log.go deleted file mode 100644 index 29760aa..0000000 --- a/internal/log/log.go +++ /dev/null @@ -1,80 +0,0 @@ -package abtrlog - -import ( - "os" - - "github.com/go-logr/logr" - "github.com/trebent/zerologr" -) - -type Opts struct { - Verbosity int - ErrorLogPath string - InfoLogPath string -} - -const ( - DefaultInfoLogPath = "info.log" - DefaultErrorLogPath = "error.log" -) - -//nolint:gochecknoglobals // package-level state for loggers -var logger logr.Logger - -// Setup sets up the loggers based on the provided options. It sets the package -// logger and returns an error logger for use by an arbiter reporter. -func Setup(opts *Opts) (logr.Logger, error) { - if opts == nil { - opts = &Opts{ - Verbosity: 0, - ErrorLogPath: "error.log", - InfoLogPath: "info.log", - } - } - - if opts.Verbosity < 0 { - opts.Verbosity = 0 - } - - if opts.ErrorLogPath == "" { - opts.ErrorLogPath = "error.log" - } - - // Set up the logger based on the provided options. - errorFile, err := os.Create(opts.ErrorLogPath) - if err != nil { - return logr.Logger{}, err - } - - if opts.InfoLogPath == "" { - logger = logr.Discard() - } else { - //nolint:govet // shad - infoFile, err := os.Create(opts.InfoLogPath) - if err != nil { - return logr.Logger{}, err - } - - logger = zerologr.New(&zerologr.Opts{ - Output: infoFile, - Console: true, - Caller: true, - V: opts.Verbosity, - }).WithName("abtr") - } - - errorLogger := zerologr.New(&zerologr.Opts{ - Output: errorFile, - Console: true, - Caller: false, - V: opts.Verbosity, - }) - - return errorLogger, nil -} - -// GetLogger returns the package logger for use by other components. Setup should be called first -// to initialize the logger before calling this function. -func GetLogger() logr.Logger { - return logger -} diff --git a/internal/otel/instrument.go b/internal/otel/instrument.go index 2f65bb3..8fdbd0b 100644 --- a/internal/otel/instrument.go +++ b/internal/otel/instrument.go @@ -4,7 +4,7 @@ import ( "context" "errors" - "github.com/trebent/zerologr" + "github.com/go-logr/logr" "go.opentelemetry.io/contrib/exporters/autoexport" "go.opentelemetry.io/contrib/instrumentation/runtime" "go.opentelemetry.io/otel" @@ -26,7 +26,7 @@ func Instrument( var shutdownFuncs []func(context.Context) error shutdown := func(ctx context.Context) error { - zerologr.Info("Shutting down OpenTelemetry SDK") + logr.FromContextOrDiscard(ctx).Info("Shutting down OpenTelemetry SDK") var err error for _, fn := range shutdownFuncs { diff --git a/pkg/report/yaml/yaml.go b/pkg/report/yaml/yaml.go index d2ad747..acae83e 100644 --- a/pkg/report/yaml/yaml.go +++ b/pkg/report/yaml/yaml.go @@ -6,7 +6,6 @@ import ( "time" "github.com/go-logr/logr" - abtrlog "github.com/maansaake/arbiter/internal/log" "github.com/maansaake/arbiter/pkg/module" "github.com/maansaake/arbiter/pkg/report" "gopkg.in/yaml.v3" @@ -23,6 +22,8 @@ type ( // The buffer size sets the number of buffered report calls that are yet // to be handled. Values < 1 will be ignored. Buffer int + // Logger is the logger used for info-level logging by the reporter. + Logger logr.Logger // ErrorLogger is a logger for the reporter to log errors to. ErrorLogger logr.Logger } @@ -32,6 +33,8 @@ type ( path string // The YAML report. report *Report + // logger is used for info-level logging. + logger logr.Logger // errorLogger is used to log errors from failed operations. errorLogger logr.Logger // Synchronizer channel to limit access to the report to 1 thread. Also @@ -41,17 +44,12 @@ type ( } ) -var ( - logger logr.Logger //nolint:gochecknoglobals // package-level state for YAML reporter - _ report.Reporter = &reporter{} -) +var _ report.Reporter = &reporter{} const yamlIndent = 2 // New creates a new YAML reporter. func New(opts *Opts) report.Reporter { - logger = abtrlog.GetLogger() - var start time.Time var buffer int if opts.Buffer > 0 { @@ -71,6 +69,7 @@ func New(opts *Opts) report.Reporter { Start: start, Modules: make(map[string]*ModuleReport), }, + logger: opts.Logger, errorLogger: opts.ErrorLogger, path: opts.Path, synchronizer: make(chan func(), buffer), @@ -82,7 +81,7 @@ func New(opts *Opts) report.Reporter { // Start the YAML reporter and run until the context is cancelled. func (r *reporter) Start(ctx context.Context) { - logger.Info("Starting reporter") + r.logger.Info("Starting reporter") go func() { for { @@ -90,7 +89,7 @@ func (r *reporter) Start(ctx context.Context) { case f := <-r.synchronizer: f() case <-ctx.Done(): - logger.Info("Reporter context closed, flushing synchronizer", "len", len(r.synchronizer)) + r.logger.Info("Reporter context closed, flushing synchronizer", "len", len(r.synchronizer)) // TODO: test buffer emptying out: @@ -103,7 +102,7 @@ func (r *reporter) Start(ctx context.Context) { break out } } - logger.Info("Synchronizer flushed, stopping reporter") + r.logger.Info("Synchronizer flushed, stopping reporter") close(r.stopped) return } @@ -127,7 +126,7 @@ func (r *reporter) ReportOp(mod, op string, res *module.Result, err error) { func (r *reporter) Finalise() error { // Await synchronizer, no value expected <-r.stopped - logger.Info("Synchronizer stopped, writing report") + r.logger.Info("Synchronizer stopped, writing report") r.report.End = time.Now() r.report.Duration = r.report.End.Sub(r.report.Start) diff --git a/pkg/report/yaml/yaml_test.go b/pkg/report/yaml/yaml_test.go index d3215d7..7a070a0 100644 --- a/pkg/report/yaml/yaml_test.go +++ b/pkg/report/yaml/yaml_test.go @@ -7,13 +7,18 @@ import ( "testing" "time" + "github.com/go-logr/logr/funcr" "github.com/maansaake/arbiter/pkg/module" "gopkg.in/yaml.v3" ) func TestYAMLReporter(t *testing.T) { reportPath := "report.yaml" - i := New(&Opts{Buffer: 100, Path: reportPath}) + i := New(&Opts{ + Buffer: 100, + Path: reportPath, + Logger: funcr.New(func(_, _ string) {}, funcr.Options{}), + }) yamlReporter := i.(*reporter) ctx := context.Background()