add logger

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
 		}
 

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())
 		}
 	}
 

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

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
 	}
 

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:

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

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")
+		log.Warn("Sub-command timed out")
-		logrus.Debugf("timeout running %s %s: %s", executable, args, stdout.String())
+		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
 }

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)
 	}

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
+}

pkg/logger/log.go

@@ -0,0 +1,91 @@
+// Copyright © 2022 Roberto Hidalgo <chinampa@un.rob.mx>
+// 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...)
+}

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))
 }