From eea360d7d677b779f9f7f647092cf348c859b6a9 Mon Sep 17 00:00:00 2001 From: Roberto Hidalgo Date: Mon, 20 Mar 2023 00:15:53 -0600 Subject: [PATCH] add logger --- internal/commands/version.go | 4 +- internal/registry/cobra.go | 3 +- internal/registry/registry.go | 6 ++- pkg/command/command.go | 18 ++++--- pkg/command/options.go | 2 +- pkg/command/value.go | 15 +++--- pkg/exec/exec.go | 12 ++--- pkg/exec/exec_test.go | 13 +++-- pkg/logger/formatter.go | 39 +++++++++++++++ pkg/logger/log.go | 91 +++++++++++++++++++++++++++++++++++ pkg/runtime/runtime.go | 5 ++ 11 files changed, 174 insertions(+), 34 deletions(-) create mode 100644 pkg/logger/formatter.go create mode 100644 pkg/logger/log.go diff --git a/internal/commands/version.go b/internal/commands/version.go index 0a09aa7..3f08760 100644 --- a/internal/commands/version.go +++ b/internal/commands/version.go @@ -5,8 +5,8 @@ package commands import ( "os" + "git.rob.mx/nidito/chinampa/pkg/logger" "git.rob.mx/nidito/chinampa/pkg/statuscode" - "github.com/sirupsen/logrus" "github.com/spf13/cobra" ) @@ -28,7 +28,7 @@ var Version = &cobra.Command{ _, err := output.Write([]byte(version)) if err != nil { - logrus.Errorf("version error: %s", err) + logger.Main.Errorf("version error: %s", err) return err } diff --git a/internal/registry/cobra.go b/internal/registry/cobra.go index 0c4ab88..863f3f4 100644 --- a/internal/registry/cobra.go +++ b/internal/registry/cobra.go @@ -10,7 +10,6 @@ import ( "git.rob.mx/nidito/chinampa/pkg/errors" "git.rob.mx/nidito/chinampa/pkg/runtime" "github.com/fatih/color" - "github.com/sirupsen/logrus" "github.com/spf13/cobra" ) @@ -92,7 +91,7 @@ func ToCobra(cmd *command.Command, globalOptions command.Options) *cobra.Command for name, opt := range cmd.Options { if err := cc.RegisterFlagCompletionFunc(name, opt.CompletionFunction); err != nil { - logrus.Errorf("Failed setting up autocompletion for option <%s> of command <%s>", name, cmd.FullName()) + log.Errorf("Failed setting up autocompletion for option <%s> of command <%s>", name, cmd.FullName()) } } diff --git a/internal/registry/registry.go b/internal/registry/registry.go index a81c85f..f9dae08 100644 --- a/internal/registry/registry.go +++ b/internal/registry/registry.go @@ -11,9 +11,9 @@ import ( "git.rob.mx/nidito/chinampa/internal/commands" "git.rob.mx/nidito/chinampa/pkg/command" "git.rob.mx/nidito/chinampa/pkg/errors" + "git.rob.mx/nidito/chinampa/pkg/logger" "git.rob.mx/nidito/chinampa/pkg/statuscode" "github.com/fatih/color" - "github.com/sirupsen/logrus" "github.com/spf13/cobra" ) @@ -22,7 +22,7 @@ const ContextKeyRuntimeIndex = "x-chinampa-runtime-index" var ErrorHandler = errors.HandleCobraExit -var log = logrus.WithField("chinampa", "registry") +var log = logger.Sub("registry") var registry = &CommandRegistry{ kv: map[string]*command.Command{}, @@ -91,6 +91,7 @@ func Execute(version string) error { if idx == len(cmd.Path)-1 { leaf := ToCobra(cmd, cmdRoot.Options) container.AddCommand(leaf) + container.ValidArgs = append(container.ValidArgs, leaf.Name()) log.Tracef("cobra: %s => %s", leaf.Name(), container.CommandPath()) break } @@ -122,6 +123,7 @@ func Execute(version string) error { Annotations: map[string]string{ ContextKeyRuntimeIndex: strings.Join(groupPath, " "), }, + ValidArgs: []string{}, Args: func(cmd *cobra.Command, args []string) error { if err := cobra.OnlyValidArgs(cmd, args); err == nil { return nil diff --git a/pkg/command/command.go b/pkg/command/command.go index 7495bae..e83728b 100644 --- a/pkg/command/command.go +++ b/pkg/command/command.go @@ -7,12 +7,14 @@ import ( "strconv" "strings" + "git.rob.mx/nidito/chinampa/pkg/logger" "git.rob.mx/nidito/chinampa/pkg/runtime" - "github.com/sirupsen/logrus" "github.com/spf13/cobra" "github.com/spf13/pflag" ) +var log = logger.Sub("chinampa:command") + type HelpFunc func(printLinks bool) string type Action func(cmd *Command) error @@ -90,7 +92,7 @@ func (cmd *Command) FlagSet() *pflag.FlagSet { case string: casted, err := strconv.Atoi(val) if err != nil { - logrus.Warnf("Could not parse default with value <%s> as integer for option <%s>", val, name) + log.Warnf("Could not parse default with value <%s> as integer for option <%s>", val, name) } def = casted } @@ -106,7 +108,7 @@ func (cmd *Command) FlagSet() *pflag.FlagSet { fs.StringP(name, opt.ShortName, def, opt.Description) default: // ignore flag - logrus.Warnf("Ignoring unknown option type <%s> for option <%s>", opt.Type, name) + log.Warnf("Ignoring unknown option type <%s> for option <%s>", opt.Type, name) continue } } @@ -121,14 +123,14 @@ func (cmd *Command) ParseInput(cc *cobra.Command, args []string) error { skipValidation, _ := cc.Flags().GetBool("skip-validation") cmd.Options.Parse(cc.Flags()) if !skipValidation { - logrus.Debug("Validating arguments") + log.Debug("Validating arguments") if err := cmd.Arguments.AreValid(); err != nil { return err } - logrus.Debug("Validating flags") + log.Debug("Validating flags") if err := cmd.Options.AreValid(); err != nil { - logrus.Debugf("Invalid flags for %s: %s", cmd.FullName(), err) + log.Debugf("Invalid flags for %s: %s", cmd.FullName(), err) return err } } @@ -137,10 +139,10 @@ func (cmd *Command) ParseInput(cc *cobra.Command, args []string) error { } func (cmd *Command) Run(cc *cobra.Command, args []string) error { - logrus.Debugf("running command %s", cmd.FullName()) + log.Debugf("running command %s", cmd.FullName()) if err := cmd.ParseInput(cc, args); err != nil { - logrus.Debugf("Parsing input to command %s failed: %s", cmd.FullName(), err) + log.Debugf("Parsing input to command %s failed: %s", cmd.FullName(), err) return err } diff --git a/pkg/command/options.go b/pkg/command/options.go index ee0d96e..f6aede0 100644 --- a/pkg/command/options.go +++ b/pkg/command/options.go @@ -32,7 +32,7 @@ func (opts *Options) AllKnownStr() map[string]string { } func (opts *Options) Parse(supplied *pflag.FlagSet) { - // logrus.Debugf("Parsing supplied flags, %v", supplied) + // log.Debugf("Parsing supplied flags, %v", supplied) for name, opt := range *opts { switch opt.Type { case ValueTypeBoolean: diff --git a/pkg/command/value.go b/pkg/command/value.go index 3beb57b..afc9a22 100644 --- a/pkg/command/value.go +++ b/pkg/command/value.go @@ -13,7 +13,6 @@ import ( "git.rob.mx/nidito/chinampa/pkg/exec" "git.rob.mx/nidito/chinampa/pkg/render" - "github.com/sirupsen/logrus" "github.com/spf13/cobra" "gopkg.in/yaml.v3" ) @@ -162,7 +161,7 @@ func (vs *ValueSource) Resolve(currentValue string) (values []string, flag cobra args := append([]string{"/bin/bash", "-c"}, cmd) - values, flag, err = exec.Exec(vs.command.FullName(), args, os.Environ(), timeout*time.Second) + values, flag, err = exec.Exec(vs.command.FullName(), args, os.Environ(), timeout*time.Second, log) if err != nil { return nil, flag, err } @@ -236,13 +235,13 @@ func (vs *ValueSource) UnmarshalYAML(node *yaml.Node) error { vs.computed = nil intermediate := map[string]yaml.Node{} if err := node.Decode(&intermediate); err != nil { - logrus.Errorf("could not decode valuesource: %s", err) + log.Errorf("could not decode valuesource: %s", err) return err } if t, ok := intermediate["timeout"]; ok { if err := t.Decode(&vs.Timeout); err != nil { - logrus.Errorf("could not decode timeout: %s", err) + log.Errorf("could not decode timeout: %s", err) return err } delete(intermediate, "timeout") @@ -250,7 +249,7 @@ func (vs *ValueSource) UnmarshalYAML(node *yaml.Node) error { if t, ok := intermediate["suggest-only"]; ok { if err := t.Decode(&vs.Suggestion); err != nil { - logrus.Errorf("could not decode suggest-only: %s", err) + log.Errorf("could not decode suggest-only: %s", err) return err } delete(intermediate, "suggest-only") @@ -258,7 +257,7 @@ func (vs *ValueSource) UnmarshalYAML(node *yaml.Node) error { if t, ok := intermediate["suggest-raw"]; ok { if err := t.Decode(&vs.SuggestRaw); err != nil { - logrus.Errorf("could not decode suggest-raw: %s", err) + log.Errorf("could not decode suggest-raw: %s", err) return err } delete(intermediate, "suggest-raw") @@ -267,7 +266,7 @@ func (vs *ValueSource) UnmarshalYAML(node *yaml.Node) error { for key, node := range intermediate { if cfn, ok := customCompleters[key]; ok { if err := node.Decode(&vs.custom); err != nil { - logrus.Errorf("could not decode custom: %s", err) + log.Errorf("could not decode custom: %s", err) return err } vs.Func = cfn @@ -294,7 +293,7 @@ func (vs *ValueSource) UnmarshalYAML(node *yaml.Node) error { case "static": static := []string{} if err := node.Decode(&static); err != nil { - logrus.Errorf("could not decode static: %s", err) + log.Errorf("could not decode static: %s", err) return err } vs.Static = &static diff --git a/pkg/exec/exec.go b/pkg/exec/exec.go index 64f61b1..2e9cef2 100644 --- a/pkg/exec/exec.go +++ b/pkg/exec/exec.go @@ -29,27 +29,27 @@ func WithSubshell(ctx context.Context, env []string, executable string, args ... } // Exec runs a subprocess and returns a list of lines from stdout. -func Exec(name string, args []string, env []string, timeout time.Duration) ([]string, cobra.ShellCompDirective, error) { +func Exec(name string, args []string, env []string, timeout time.Duration, log *logrus.Entry) ([]string, cobra.ShellCompDirective, error) { ctx, cancel := context.WithTimeout(context.Background(), timeout) defer cancel() // The cancel should be deferred so resources are cleaned up - logrus.Debugf("executing %s", args) + log.Tracef("executing a subshell for %s", args) executable := args[0] args = args[1:] stdout, _, err := ExecFunc(ctx, env, executable, args...) if ctx.Err() == context.DeadlineExceeded { - fmt.Println("Sub-command timed out") - logrus.Debugf("timeout running %s %s: %s", executable, args, stdout.String()) + log.Warn("Sub-command timed out") + log.Debugf("timeout running %s %s: %s", executable, args, stdout.String()) return []string{}, cobra.ShellCompDirectiveError, fmt.Errorf("timed out resolving %s %s", executable, args) } if err != nil { - logrus.Debugf("error running %s %s: %s", executable, args, err) + log.Debugf("error running %s %s: %s", executable, args, err) return []string{}, cobra.ShellCompDirectiveError, errors.BadArguments{Msg: fmt.Sprintf("could not validate argument for command %s, ran <%s %s> failed: %s", name, executable, strings.Join(args, " "), err)} } - logrus.Debugf("done running %s %s: %s", executable, args, stdout.String()) + log.Tracef("finished running %s %s: %s", executable, args, stdout.String()) return strings.Split(strings.TrimSuffix(stdout.String(), "\n"), "\n"), cobra.ShellCompDirectiveDefault, nil } diff --git a/pkg/exec/exec_test.go b/pkg/exec/exec_test.go index 6cf45f9..7b9bb6a 100644 --- a/pkg/exec/exec_test.go +++ b/pkg/exec/exec_test.go @@ -11,12 +11,15 @@ import ( "time" . "git.rob.mx/nidito/chinampa/pkg/exec" + "github.com/sirupsen/logrus" "github.com/spf13/cobra" ) +var logger = logrus.WithContext(context.Background()) + func TestSubshellExec(t *testing.T) { ExecFunc = WithSubshell - stdout, directive, err := Exec("test-command", []string{"bash", "-c", `echo "stdout"; echo "stderr" >&2;`}, []string{}, 1*time.Second) + stdout, directive, err := Exec("test-command", []string{"bash", "-c", `echo "stdout"; echo "stderr" >&2;`}, []string{}, 1*time.Second, logger) if err != nil { t.Fatalf("good subshell errored: %v", err) } @@ -29,7 +32,7 @@ func TestSubshellExec(t *testing.T) { t.Fatalf("good subshell returned wrong directive: %v", directive) } - stdout, directive, err = Exec("test-command", []string{"bash", "-c", `echo "stdout"; echo "stderr" >&2; exit 2`}, []string{}, 1*time.Second) + stdout, directive, err = Exec("test-command", []string{"bash", "-c", `echo "stdout"; echo "stderr" >&2; exit 2`}, []string{}, 1*time.Second, logger) if err == nil { t.Fatalf("bad subshell did not error; stdout: %v", stdout) } @@ -48,7 +51,7 @@ func TestExecTimesOut(t *testing.T) { time.Sleep(100 * time.Nanosecond) return bytes.Buffer{}, bytes.Buffer{}, context.DeadlineExceeded } - _, _, err := Exec("test-command", []string{"bash", "-c", "sleep", "2"}, []string{}, 10*time.Nanosecond) + _, _, err := Exec("test-command", []string{"bash", "-c", "sleep", "2"}, []string{}, 10*time.Nanosecond, logger) if err == nil { t.Fatalf("timeout didn't happen after 10ms: %v", err) } @@ -65,7 +68,7 @@ func TestExecWorksFine(t *testing.T) { return out, bytes.Buffer{}, nil } args := []string{"a", "b", "c"} - res, directive, err := Exec("test-command", append([]string{"bash", "-c", "echo"}, args...), []string{}, 1*time.Second) + res, directive, err := Exec("test-command", append([]string{"bash", "-c", "echo"}, args...), []string{}, 1*time.Second, logger) if err != nil { t.Fatalf("good command failed: %v", err) } @@ -83,7 +86,7 @@ func TestExecErrors(t *testing.T) { ExecFunc = func(ctx context.Context, env []string, executable string, args ...string) (bytes.Buffer, bytes.Buffer, error) { return bytes.Buffer{}, bytes.Buffer{}, fmt.Errorf("bad command is bad") } - res, directive, err := Exec("test-command", []string{"bash", "-c", "bad-command"}, []string{}, 1*time.Second) + res, directive, err := Exec("test-command", []string{"bash", "-c", "bad-command"}, []string{}, 1*time.Second, logger) if err == fmt.Errorf("bad command is bad") { t.Fatalf("bad command didn't fail: %v", res) } diff --git a/pkg/logger/formatter.go b/pkg/logger/formatter.go new file mode 100644 index 0000000..97a9ff2 --- /dev/null +++ b/pkg/logger/formatter.go @@ -0,0 +1,39 @@ +package logger + +import ( + "fmt" + "strings" + "time" + + "git.rob.mx/nidito/chinampa/pkg/runtime" + "github.com/sirupsen/logrus" +) + +type Formatter struct { +} + +func (f *Formatter) Format(entry *logrus.Entry) ([]byte, error) { + prefix := "" + colorEnabled := runtime.ColorEnabled() + if runtime.VerboseEnabled() { + date := strings.Replace(entry.Time.Local().Format(time.DateTime), " ", "T", 1) + component := "" + if c, ok := entry.Data[componentKey]; ok { + component = " " + c.(string) + } + prefix = fmt.Sprintf("\033[2m%s %s%s\033[0m\t", date, entry.Level.String(), component) + } else if entry.Level == logrus.ErrorLevel { + if colorEnabled { + prefix = "\033[41m\033[1m ERROR \033[0m " + } else { + prefix = "ERROR: " + } + } else if entry.Level == logrus.WarnLevel { + if colorEnabled { + prefix = "\033[43m\033[31m warning \033[0m " + } else { + prefix = "WARNING: " + } + } + return []byte(prefix + entry.Message + "\n"), nil +} diff --git a/pkg/logger/log.go b/pkg/logger/log.go new file mode 100644 index 0000000..59bc071 --- /dev/null +++ b/pkg/logger/log.go @@ -0,0 +1,91 @@ +// Copyright © 2022 Roberto Hidalgo +// SPDX-License-Identifier: Apache-2.0 +package logger + +import ( + "context" + + "git.rob.mx/nidito/chinampa/pkg/runtime" + "github.com/sirupsen/logrus" +) + +var componentKey = "_component" + +func init() { + logrus.SetFormatter(new(Formatter)) +} + +var Main = logrus.WithContext(context.Background()) + +func Sub(name string) *logrus.Entry { + return logrus.WithField(componentKey, name) +} + +type Level int + +const ( + LevelPanic Level = iota + LevelFatal + LevelError + LevelWarning + LevelInfo + LevelDebug + LevelTrace +) + +func Configure(name string, level Level) { + Main = logrus.WithField(componentKey, name) + if runtime.SilenceEnabled() { + logrus.SetLevel(logrus.ErrorLevel) + } else { + logrus.SetLevel(logrus.AllLevels[level]) + } +} + +func Debug(args ...any) { + Main.Debug(args...) +} + +func Debugf(format string, args ...any) { + Main.Debugf(format, args...) +} + +func Info(args ...any) { + Main.Info(args...) +} + +func Infof(format string, args ...any) { + Main.Infof(format, args...) +} + +func Warn(args ...any) { + Main.Warn(args...) +} + +func Warnf(format string, args ...any) { + Main.Warnf(format, args...) +} + +func Error(args ...any) { + Main.Error(args...) +} + +func Errorf(format string, args ...any) { + Main.Errorf(format, args...) +} + +func Fatal(args ...any) { + Main.Fatal(args...) +} + +func Fatalf(format string, args ...any) { + Main.Fatalf(format, args...) +} + +func Trace(args ...any) { + Main.Trace(args...) +} + +func Tracef(format string, args ...any) { + Main.Tracef(format, args...) +} diff --git a/pkg/runtime/runtime.go b/pkg/runtime/runtime.go index b69f0cd..92f4a55 100644 --- a/pkg/runtime/runtime.go +++ b/pkg/runtime/runtime.go @@ -61,6 +61,11 @@ func ValidationEnabled() bool { } func VerboseEnabled() bool { + for _, arg := range os.Args { + if arg == "--verbose" { + return true + } + } return isTrueIsh(os.Getenv(env.Verbose)) }