From 5c8fb868ca421f31bd60e0e8cb4524ed8df56ecc Mon Sep 17 00:00:00 2001 From: Andrew Morozko Date: Sun, 11 Feb 2024 23:20:12 +0400 Subject: [PATCH] Colored logs (#75) --- cmd/render.go | 4 +- cmd/root.go | 40 ++++++++++++-- go.mod | 8 ++- go.sum | 4 ++ pkg/diagnostics/printer.go | 30 +++++++--- pkg/sloghclog/sloghclog.go | 42 +++++++++++--- pkg/sloghclog/sloghclog_test.go | 98 +++++++++++++++++++++++++++++++++ plugin/pluginapi/v1/client.go | 2 + 8 files changed, 206 insertions(+), 22 deletions(-) diff --git a/cmd/render.go b/cmd/render.go index 0d9f943e..38aa00fb 100644 --- a/cmd/render.go +++ b/cmd/render.go @@ -21,7 +21,9 @@ var outFile string func render(dest io.Writer, docName string) { result := parser.ParseDir(os.DirFS(cliArgs.sourceDir)) diags := result.Diags - defer func() { diagnostics.PrintDiags(diags, result.FileMap) }() + defer func() { + diagnostics.PrintDiags(os.Stderr, diags, result.FileMap, cliArgs.colorize) + }() if diags.HasErrors() { return } diff --git a/cmd/root.go b/cmd/root.go index eabdd29c..1d70f3c6 100644 --- a/cmd/root.go +++ b/cmd/root.go @@ -3,12 +3,17 @@ package cmd import ( "errors" "fmt" + "io" "log/slog" "os" "slices" "strings" + "github.com/golang-cz/devslog" + "github.com/lmittmann/tint" + "github.com/mattn/go-colorable" "github.com/spf13/cobra" + "golang.org/x/term" "github.com/blackstork-io/fabric/pkg/utils" ) @@ -88,6 +93,8 @@ var rootCmd = &cobra.Command{ } cliArgs.pluginsDir = rawArgs.pluginsDir + cliArgs.colorize = rawArgs.colorize && term.IsTerminal(int(os.Stderr.Fd())) + var level slog.Level if rawArgs.verbose { level = slog.LevelDebug @@ -103,17 +110,39 @@ var rootCmd = &cobra.Command{ AddSource: level == slog.LevelDebug, } - var logger *slog.Logger + var handler slog.Handler switch strings.ToLower(strings.TrimSpace(rawArgs.logOutput)) { case "plain": - logger = slog.New(slog.NewTextHandler(os.Stderr, opts)) + if cliArgs.colorize && level <= slog.LevelDebug { + handler = devslog.NewHandler(os.Stderr, &devslog.Options{ + HandlerOptions: opts, + }) + } else { + var output io.Writer + if cliArgs.colorize { + // only affects windows, noop on *nix + output = colorable.NewColorable(os.Stderr) + } else { + output = os.Stderr + } + + handler = tint.NewHandler( + output, + &tint.Options{ + AddSource: opts.AddSource, + Level: opts.Level, + ReplaceAttr: opts.ReplaceAttr, + NoColor: !cliArgs.colorize, + }, + ) + } case "json": - logger = slog.New(slog.NewJSONHandler(os.Stderr, opts)) + handler = slog.NewJSONHandler(os.Stderr, opts) default: return fmt.Errorf("unknown log output '%s'", rawArgs.logOutput) } - slog.SetDefault(logger) + slog.SetDefault(slog.New(handler)) slog.Debug("Logging enabled") if version == devVersion { slog.Warn("This is a dev version of the software") @@ -134,6 +163,7 @@ func Execute() { var cliArgs = struct { sourceDir string pluginsDir string + colorize bool }{} var rawArgs = struct { @@ -142,6 +172,7 @@ var rawArgs = struct { logLevel string pluginsDir string verbose bool + colorize bool }{} func init() { @@ -151,6 +182,7 @@ func init() { &rawArgs.logLevel, "log-level", "info", fmt.Sprintf("logging level (%s)", validLogLevels.String()), ) + rootCmd.PersistentFlags().BoolVar(&rawArgs.colorize, "color", true, "enables colorizing the logs and diagnostics (if supported by the terminal and log format)") rootCmd.PersistentFlags().BoolVarP(&rawArgs.verbose, "verbose", "v", false, "a shortcut to --log-level debug") // TODO: after #5 is implemented - make optional rootCmd.PersistentFlags().StringVar( diff --git a/go.mod b/go.mod index db0289e2..0615d0ab 100644 --- a/go.mod +++ b/go.mod @@ -1,15 +1,20 @@ module github.com/blackstork-io/fabric -go 1.21 +go 1.21.0 + +toolchain go1.21.1 require ( github.com/elastic/go-elasticsearch/v8 v8.11.1 + github.com/golang-cz/devslog v0.0.8 github.com/google/go-github/v58 v58.0.0 github.com/hashicorp/go-hclog v0.14.1 github.com/hashicorp/go-plugin v1.6.0 github.com/hashicorp/hcl/v2 v2.19.1 github.com/itchyny/gojq v0.12.14 github.com/lib/pq v1.10.9 + github.com/lmittmann/tint v1.0.4 + github.com/mattn/go-colorable v0.1.13 github.com/mattn/go-sqlite3 v1.14.20 github.com/pelletier/go-toml/v2 v2.1.1 github.com/sanity-io/litter v1.5.5 @@ -60,7 +65,6 @@ require ( github.com/klauspost/compress v1.17.0 // indirect github.com/lufia/plan9stats v0.0.0-20211012122336-39d0f177ccd0 // indirect github.com/magiconair/properties v1.8.7 // indirect - github.com/mattn/go-colorable v0.1.13 // indirect github.com/mattn/go-isatty v0.0.20 // indirect github.com/mitchellh/go-testing-interface v0.0.0-20171004221916-a61a99592b77 // indirect github.com/mitchellh/go-wordwrap v0.0.0-20150314170334-ad45545899c7 // indirect diff --git a/go.sum b/go.sum index 71933d03..0ad2e760 100644 --- a/go.sum +++ b/go.sum @@ -68,6 +68,8 @@ github.com/godbus/dbus/v5 v5.0.4/go.mod h1:xhWf0FNVPg57R7Z0UbKHbJfkEywrmjJnf7w5x github.com/godbus/dbus/v5 v5.0.6/go.mod h1:xhWf0FNVPg57R7Z0UbKHbJfkEywrmjJnf7w5xrFpKfA= github.com/gogo/protobuf v1.3.2 h1:Ov1cvc58UF3b5XjBnZv7+opcTcQFZebYjWzi34vdm4Q= github.com/gogo/protobuf v1.3.2/go.mod h1:P1XiOD3dCwIKUDQYPy72D8LYyHL2YPYrpS2s69NZV8Q= +github.com/golang-cz/devslog v0.0.8 h1:53ipA2rC5JzWBWr9qB8EfenvXppenNiF/8DwgtNT5Q4= +github.com/golang-cz/devslog v0.0.8/go.mod h1:bSe5bm0A7Nyfqtijf1OMNgVJHlWEuVSXnkuASiE1vV8= github.com/golang/protobuf v1.5.0/go.mod h1:FsONVRAS9T7sI+LIUmWTfcYkHO4aIWwzhcaSAoJOfIk= github.com/golang/protobuf v1.5.3 h1:KhyjKVUg7Usr/dYsdSqoFveMYd5ko72D+zANwlG1mmg= github.com/golang/protobuf v1.5.3/go.mod h1:XVQd3VNwM+JqD3oG2Ue2ip4fOMUkwXdXDdiuN0vRsmY= @@ -117,6 +119,8 @@ github.com/kylelemons/godebug v0.0.0-20170820004349-d65d576e9348 h1:MtvEpTB6LX3v github.com/kylelemons/godebug v0.0.0-20170820004349-d65d576e9348/go.mod h1:B69LEHPfb2qLo0BaaOLcbitczOKLWTsrBG9LczfCD4k= github.com/lib/pq v1.10.9 h1:YXG7RB+JIjhP29X+OtkiDnYaXQwpS4JEWq7dtCCRUEw= github.com/lib/pq v1.10.9/go.mod h1:AlVN5x4E4T544tWzH6hKfbfQvm3HdbOxrmggDNAPY9o= +github.com/lmittmann/tint v1.0.4 h1:LeYihpJ9hyGvE0w+K2okPTGUdVLfng1+nDNVR4vWISc= +github.com/lmittmann/tint v1.0.4/go.mod h1:HIS3gSy7qNwGCj+5oRjAutErFBl4BzdQP6cJZ0NfMwE= github.com/lufia/plan9stats v0.0.0-20211012122336-39d0f177ccd0 h1:6E+4a0GO5zZEnZ81pIr0yLvtUWk2if982qA3F3QD6H4= github.com/lufia/plan9stats v0.0.0-20211012122336-39d0f177ccd0/go.mod h1:zJYVVT2jmtg6P3p1VtQj7WsuWi/y4VnjVBn7F8KPB3I= github.com/magiconair/properties v1.8.7 h1:IeQXZAiQcpL9mgcAe1Nu6cX9LLw6ExEHKjN0VQdvPDY= diff --git a/pkg/diagnostics/printer.go b/pkg/diagnostics/printer.go index 8ba7545d..d0dc44b0 100644 --- a/pkg/diagnostics/printer.go +++ b/pkg/diagnostics/printer.go @@ -2,30 +2,46 @@ package diagnostics import ( "bufio" + "io" + "log/slog" "os" "github.com/hashicorp/hcl/v2" + "github.com/mattn/go-colorable" "golang.org/x/term" ) -func PrintDiags(diags Diag, fileMap map[string]*hcl.File) { +func PrintDiags(output *os.File, diags Diag, fileMap map[string]*hcl.File, colorize bool) { if len(diags) == 0 { return } - colorize := term.IsTerminal(0) - width, _, err := term.GetSize(0) + width, _, err := term.GetSize(int(output.Fd())) if err != nil || width <= 0 { width = 80 } - wr := bufio.NewWriter(os.Stderr) - diagWriter := hcl.NewDiagnosticTextWriter(wr, fileMap, uint(width), colorize) + + var wr io.Writer = output + if colorize { + wr = colorable.NewColorable(output) + } + bufWr := bufio.NewWriter(wr) + defer func() { + err := bufWr.Flush() + if err != nil { + slog.Error("Failed to flush diagnostics", "err", err) + } + }() + + diagWriter := hcl.NewDiagnosticTextWriter(bufWr, fileMap, uint(width), colorize) for _, diag := range diags { if _, isRepeated := hcl.DiagnosticExtra[repeatedError](diag); isRepeated { continue } - diagWriter.WriteDiagnostic(diag) + err := diagWriter.WriteDiagnostic(diag) + if err != nil { + slog.Error("Failed to write diagnostics", "err", err) + } } - wr.Flush() } diff --git a/pkg/sloghclog/sloghclog.go b/pkg/sloghclog/sloghclog.go index a7eb54ac..444d5e77 100644 --- a/pkg/sloghclog/sloghclog.go +++ b/pkg/sloghclog/sloghclog.go @@ -6,24 +6,32 @@ import ( "io" "log" "log/slog" + "math" "runtime" "time" "github.com/hashicorp/go-hclog" ) +const ( + LevelTrace slog.Level = slog.Level(-8) + minLevel = slog.Level(math.MinInt) +) + type adapter struct { origLogger *slog.Logger logger *slog.Logger name string with []any addSource bool + leveler slog.Leveler } func Adapt(logger *slog.Logger, opts ...adapterOption) hclog.Logger { a := &adapter{ origLogger: logger, logger: logger, + leveler: minLevel, } for _, opt := range opts { opt.apply(a) @@ -54,7 +62,11 @@ func Name(val string) adapterOption { }) } -const LevelTrace slog.Level = slog.Level(-8) +func Level(level slog.Leveler) adapterOption { + return funcAdapterOption(func(a *adapter) { + a.leveler = level + }) +} func convertLevel(level hclog.Level) slog.Level { if level == hclog.NoLevel { @@ -71,13 +83,21 @@ func (a *adapter) Log(level hclog.Level, msg string, args ...interface{}) { a.log(level, msg, args...) } +func (a *adapter) enabled(level slog.Level) bool { + return a.leveler.Level() <= level && a.logger.Enabled(context.Background(), level) +} + func (a *adapter) log(level hclog.Level, msg string, args ...interface{}) { + lvl := convertLevel(level) + if !a.enabled(lvl) { + return + } var pcs [1]uintptr if a.addSource { // skip [Callers, log, (Log|Info|...)] runtime.Callers(3, pcs[:]) } - r := slog.NewRecord(time.Now(), convertLevel(level), msg, pcs[0]) + r := slog.NewRecord(time.Now(), lvl, msg, pcs[0]) r.Add(args...) _ = a.logger.Handler().Handle(context.Background(), r) } @@ -110,27 +130,27 @@ func (a *adapter) Error(msg string, args ...interface{}) { // Indicate if TRACE logs would be emitted. This and the other Is* guards // are used to elide expensive logging code based on the current level. func (a *adapter) IsTrace() bool { - return a.logger.Enabled(context.Background(), LevelTrace) + return a.enabled(LevelTrace) } // Indicate if DEBUG logs would be emitted. This and the other Is* guards func (a *adapter) IsDebug() bool { - return a.logger.Enabled(context.Background(), slog.LevelDebug) + return a.enabled(slog.LevelDebug) } // Indicate if INFO logs would be emitted. This and the other Is* guards func (a *adapter) IsInfo() bool { - return a.logger.Enabled(context.Background(), slog.LevelInfo) + return a.enabled(slog.LevelInfo) } // Indicate if WARN logs would be emitted. This and the other Is* guards func (a *adapter) IsWarn() bool { - return a.logger.Enabled(context.Background(), slog.LevelWarn) + return a.enabled(slog.LevelWarn) } // Indicate if ERROR logs would be emitted. This and the other Is* guards func (a *adapter) IsError() bool { - return a.logger.Enabled(context.Background(), slog.LevelError) + return a.enabled(slog.LevelError) } // ImpliedArgs returns With key/value pairs @@ -217,7 +237,13 @@ func (a *adapter) ResetNamed(name string) hclog.Logger { // Updates the level. This should affect all sub-loggers as well. If an // implementation cannot update the level on the fly, it should no-op. func (a *adapter) SetLevel(level hclog.Level) { - // no-op: we can't be sure that we can update the level + type settableLeveler interface { + Set(l slog.Level) + } + setter, ok := a.leveler.(settableLeveler) + if ok { + setter.Set(convertLevel(level)) + } } // Return a value that conforms to the stdlib log.Logger interface diff --git a/pkg/sloghclog/sloghclog_test.go b/pkg/sloghclog/sloghclog_test.go index 4ce2475f..620c3c5e 100644 --- a/pkg/sloghclog/sloghclog_test.go +++ b/pkg/sloghclog/sloghclog_test.go @@ -68,11 +68,107 @@ func Test_isLevel(t *testing.T) { } } +func Test_levelRespected(t *testing.T) { + t.Parallel() + assert := assert.New(t) + buf := &bytes.Buffer{} + + for _, logLevel := range []slog.Level{slog.LevelDebug, slog.LevelInfo} { + for _, adapterLevel := range []slog.Level{minLevel, slog.LevelDebug, slog.LevelInfo} { + logger := slog.New(slog.NewTextHandler(buf, &slog.HandlerOptions{ + Level: logLevel, + })) + var a hclog.Logger + if adapterLevel == minLevel { + a = Adapt(logger) + } else { + a = Adapt(logger, Level(adapterLevel)) + } + for _, msgLevel := range []hclog.Level{hclog.Debug, hclog.Info} { + slogMsgLevel := convertLevel(msgLevel) + a.Log(msgLevel, "test") + msg := readBuf(buf) + if logLevel <= slogMsgLevel && adapterLevel <= slogMsgLevel { + assert.NotEmpty(msg) + } else { + assert.Empty(msg) + } + } + } + } + + levels := []slog.Level{ + LevelTrace, + slog.LevelDebug, + slog.LevelInfo, + slog.LevelWarn, + slog.LevelError, + } + for _, logLevel := range levels { + a := Adapt(slog.New(slog.NewTextHandler(io.Discard, &slog.HandlerOptions{ + Level: logLevel, + }))) + assert.Equal(logLevel <= LevelTrace, a.IsTrace()) + assert.Equal(logLevel <= slog.LevelDebug, a.IsDebug()) + assert.Equal(logLevel <= slog.LevelInfo, a.IsInfo()) + assert.Equal(logLevel <= slog.LevelWarn, a.IsWarn()) + assert.Equal(logLevel <= slog.LevelError, a.IsError()) + } +} + +func Test_levelSettable(t *testing.T) { + t.Parallel() + assert := assert.New(t) + buf := &bytes.Buffer{} + + for _, logLevel := range []slog.Level{slog.LevelDebug, slog.LevelInfo} { + a := Adapt( + slog.New(slog.NewTextHandler(buf, &slog.HandlerOptions{ + Level: logLevel, + })), + Level(&slog.LevelVar{}), + ) + for _, adapterLevel := range []hclog.Level{hclog.Trace, hclog.Debug, hclog.Info} { + a.SetLevel(adapterLevel) + for _, msgLevel := range []hclog.Level{hclog.Trace, hclog.Debug, hclog.Info} { + slogMsgLevel := convertLevel(msgLevel) + a.Log(msgLevel, "test") + msg := readBuf(buf) + if logLevel <= slogMsgLevel && adapterLevel <= msgLevel { + assert.NotEmpty(msg) + } else { + assert.Empty(msg) + } + } + } + + } + + levels := []slog.Level{ + LevelTrace, + slog.LevelDebug, + slog.LevelInfo, + slog.LevelWarn, + slog.LevelError, + } + for _, logLevel := range levels { + a := Adapt(slog.New(slog.NewTextHandler(io.Discard, &slog.HandlerOptions{ + Level: logLevel, + }))) + assert.Equal(logLevel <= LevelTrace, a.IsTrace()) + assert.Equal(logLevel <= slog.LevelDebug, a.IsDebug()) + assert.Equal(logLevel <= slog.LevelInfo, a.IsInfo()) + assert.Equal(logLevel <= slog.LevelWarn, a.IsWarn()) + assert.Equal(logLevel <= slog.LevelError, a.IsError()) + } +} + func readBuf(buf *bytes.Buffer) string { return string(buf.Next(buf.Len())) } func Test_adapterName(t *testing.T) { + t.Parallel() assert := assert.New(t) buf := &bytes.Buffer{} @@ -121,6 +217,7 @@ func Test_adapterName(t *testing.T) { } func Test_adapterIndependance(t *testing.T) { + t.Parallel() t.Run("calling named funcs doesn't affect the parent", func(t *testing.T) { t.Parallel() assert := assert.New(t) @@ -242,6 +339,7 @@ func Test_adapterIndependance(t *testing.T) { } func Test_adapterOpts(t *testing.T) { + t.Parallel() t.Run("Option Name", func(t *testing.T) { t.Parallel() buf := &bytes.Buffer{} diff --git a/plugin/pluginapi/v1/client.go b/plugin/pluginapi/v1/client.go index b4db4635..b3d5bc81 100644 --- a/plugin/pluginapi/v1/client.go +++ b/plugin/pluginapi/v1/client.go @@ -35,6 +35,7 @@ func NewClient(loc string) (p *plugin.Schema, closefn func() error, err error) { if err != nil { return } + slog.Info("Loading plugin", "filename", loc) client := goplugin.NewClient(&goplugin.ClientConfig{ HandshakeConfig: handshake, Plugins: map[string]goplugin.Plugin{ @@ -50,6 +51,7 @@ func NewClient(loc string) (p *plugin.Schema, closefn func() error, err error) { // disable code location reporting, it's always going to be incorrect // for remote plugin logs sloghclog.AddSource(false), + sloghclog.Level(slog.LevelInfo), // debug is too noisy for plugins ), }) rpcClient, err := client.Client()