diff --git a/cmd/root/logger.go b/cmd/root/logger.go new file mode 100644 index 00000000..ebe65f60 --- /dev/null +++ b/cmd/root/logger.go @@ -0,0 +1,50 @@ +package root + +import ( + "context" + "fmt" + + "github.com/databricks/bricks/libs/flags" + "github.com/databricks/bricks/libs/log" + "github.com/spf13/cobra" + "golang.org/x/exp/slog" +) + +func initializeLogger(ctx context.Context, cmd *cobra.Command) (context.Context, error) { + opts := slog.HandlerOptions{} + opts.Level = logLevel.Level() + opts.AddSource = true + opts.ReplaceAttr = log.ReplaceLevelAttr + + // Open the underlying log file if the user configured an actual file to log to. + err := logFile.Open() + if err != nil { + return nil, err + } + + var handler slog.Handler + switch logOutput { + case flags.OutputJSON: + handler = opts.NewJSONHandler(logFile.Writer()) + case flags.OutputText: + handler = opts.NewTextHandler(logFile.Writer()) + default: + return nil, fmt.Errorf("invalid log output: %s", logOutput) + } + + slog.SetDefault(slog.New(handler)) + return log.NewContext(ctx, slog.Default()), nil +} + +var logFile = flags.NewLogFileFlag() +var logLevel = flags.NewLogLevelFlag() +var logOutput = flags.OutputText + +func init() { + RootCmd.PersistentFlags().Var(&logFile, "log-file", "file to write logs to") + RootCmd.PersistentFlags().Var(&logLevel, "log-level", "log level") + RootCmd.PersistentFlags().Var(&logOutput, "log-format", "log output format (text or json)") + RootCmd.RegisterFlagCompletionFunc("log-file", logFile.Complete) + RootCmd.RegisterFlagCompletionFunc("log-level", logLevel.Complete) + RootCmd.RegisterFlagCompletionFunc("log-format", logOutput.Complete) +} diff --git a/cmd/root/root.go b/cmd/root/root.go index ac9116bc..195e4562 100644 --- a/cmd/root/root.go +++ b/cmd/root/root.go @@ -3,9 +3,7 @@ package root import ( "context" "fmt" - "log" "os" - "strings" "github.com/spf13/cobra" ) @@ -22,40 +20,21 @@ var RootCmd = &cobra.Command{ // The usage string is include in [flagErrorFunc] for flag errors only. SilenceUsage: true, - PersistentPreRun: func(cmd *cobra.Command, args []string) { + PersistentPreRunE: func(cmd *cobra.Command, args []string) error { ctx := cmd.Context() + // Configure default logger. + ctx, err := initializeLogger(ctx, cmd) + if err != nil { + return err + } + // Configure our user agent with the command that's about to be executed. ctx = withCommandInUserAgent(ctx, cmd) ctx = withUpstreamInUserAgent(ctx) cmd.SetContext(ctx) - - if Verbose { - logLevel = append(logLevel, "[DEBUG]") - } - log.SetOutput(&logLevel) + return nil }, - - // Uncomment the following line if your bare application - // has an action associated with it: -} - -// TODO: replace with zerolog -type levelWriter []string - -var logLevel = levelWriter{"[INFO]", "[ERROR]", "[WARN]"} - -// Verbose means additional debug information, like API logs -var Verbose bool - -func (lw *levelWriter) Write(p []byte) (n int, err error) { - a := string(p) - for _, l := range *lw { - if strings.Contains(a, l) { - return os.Stderr.Write(p) - } - } - return } // Wrap flag errors to include the usage string. @@ -76,6 +55,9 @@ func Execute() { func init() { RootCmd.SetFlagErrorFunc(flagErrorFunc) - // flags available for every child command - RootCmd.PersistentFlags().BoolVarP(&Verbose, "verbose", "v", false, "print debug logs") + + // The VS Code extension passes `-v` in debug mode and must be changed + // to use the new flags in `./logger.go` prior to removing this flag. + RootCmd.PersistentFlags().BoolP("verbose", "v", false, "") + RootCmd.PersistentFlags().MarkHidden("verbose") } diff --git a/docs/output.md b/docs/output.md new file mode 100644 index 00000000..51106465 --- /dev/null +++ b/docs/output.md @@ -0,0 +1,20 @@ +# Principles for CLI output + +There are four types of output: +1. Command output +2. Command error +3. Progress reporting +4. Logging + +We try to adhere to the following rules: +* On success, the command's primary output is written to standard output. + This is required to make commands composable in scripts. +* On error, the command's error message is written to standard error + and the command exits with a non-zero exit code. +* Progress reporting may be provided to standard error, + iff standard error is a TTY _and_ logging is disabled _or_ the logging + output is different from standard error. +* Logging must be enabled explicitly. + If enabled, it writes to standard error by default. + Logging is **only** an aid to investigate issues and must not be relied + on for command output, command errors, or progress reporting. diff --git a/go.mod b/go.mod index 2059703d..9091aaa3 100644 --- a/go.mod +++ b/go.mod @@ -24,7 +24,7 @@ require ( github.com/hashicorp/hc-install v0.5.0 github.com/hashicorp/terraform-exec v0.18.1 github.com/hashicorp/terraform-json v0.16.0 - golang.org/x/exp v0.0.0-20221031165847-c99f073a8326 + golang.org/x/exp v0.0.0-20230310171629-522b1b587ee0 golang.org/x/sync v0.1.0 ) diff --git a/go.sum b/go.sum index d9deec5b..cc5d5f5b 100644 --- a/go.sum +++ b/go.sum @@ -203,8 +203,8 @@ golang.org/x/crypto v0.0.0-20210921155107-089bfa567519/go.mod h1:GvvjBRRGRdwPK5y golang.org/x/crypto v0.5.0 h1:U/0M97KRkSFvyD/3FSmdP5W5swImpNgle/EHFhOsQPE= golang.org/x/crypto v0.5.0/go.mod h1:NK/OQwhpMQP3MwtdjgLlYHnH9ebylxKWv3e0fK+mkQU= golang.org/x/exp v0.0.0-20190121172915-509febef88a4/go.mod h1:CJ0aWSM057203Lf6IL+f9T1iT9GByDxfZKAQTCR3kQA= -golang.org/x/exp v0.0.0-20221031165847-c99f073a8326 h1:QfTh0HpN6hlw6D3vu8DAwC8pBIwikq0AI1evdm+FksE= -golang.org/x/exp v0.0.0-20221031165847-c99f073a8326/go.mod h1:CxIveKay+FTh1D0yPZemJVgC/95VzuuOLq5Qi4xnoYc= +golang.org/x/exp v0.0.0-20230310171629-522b1b587ee0 h1:LGJsf5LRplCck6jUCH3dBL2dmycNruWNF5xugkSlfXw= +golang.org/x/exp v0.0.0-20230310171629-522b1b587ee0/go.mod h1:CxIveKay+FTh1D0yPZemJVgC/95VzuuOLq5Qi4xnoYc= golang.org/x/lint v0.0.0-20181026193005-c67002cb31c3/go.mod h1:UVdnD1Gm6xHRNCYTkRU2/jEulfH38KcIWyp/GAMgvoE= golang.org/x/lint v0.0.0-20190227174305-5b3e6a55c961/go.mod h1:wehouNa3lNwaWXcvxsM5YxQ5yQlVC4a0KAMCusXpPoU= golang.org/x/lint v0.0.0-20190313153728-d0100b6bd8b3/go.mod h1:6SW0HCj/g11FgYtHlgUYUwCkIfeOF89ocIRzGO/8vkc= diff --git a/libs/flags/log_file_flag.go b/libs/flags/log_file_flag.go new file mode 100644 index 00000000..9e60353f --- /dev/null +++ b/libs/flags/log_file_flag.go @@ -0,0 +1,110 @@ +package flags + +import ( + "io" + "os" + "strings" + + "github.com/spf13/cobra" +) + +// Abstract over files that are already open (e.g. stderr) and +// files that need to be opened before use. +type logFile interface { + Writer() io.Writer + Open() error + Close() error +} + +// nopLogFile implements [logFile] for [os.Stderr] and [os.Stdout]. +// The [logFile.Open] and [logFile.Close] functions do nothing. +type nopLogFile struct { + f *os.File +} + +func (f *nopLogFile) Writer() io.Writer { + return f.f +} + +func (f *nopLogFile) Open() error { + return nil +} + +func (f *nopLogFile) Close() error { + return nil +} + +// nopLogFile implements [logFile] for actual files. +type realLogFile struct { + s string + f *os.File +} + +func (f *realLogFile) Writer() io.Writer { + if f.f == nil { + panic("file hasn't been opened") + } + return f.f +} + +func (f *realLogFile) Open() error { + file, err := os.OpenFile(f.s, os.O_CREATE|os.O_WRONLY|os.O_APPEND, 0600) + if err != nil { + return err + } + + f.f = file + return nil +} + +func (f *realLogFile) Close() error { + if f.f == nil { + return nil + } + return f.f.Close() +} + +type LogFileFlag struct { + name string + logFile +} + +func NewLogFileFlag() LogFileFlag { + return LogFileFlag{ + name: "stderr", + logFile: &nopLogFile{os.Stderr}, + } +} + +func (f *LogFileFlag) String() string { + return f.name +} + +func (f *LogFileFlag) Set(s string) error { + lower := strings.ToLower(s) + switch lower { + case "stderr": + f.name = lower + f.logFile = &nopLogFile{os.Stderr} + case "stdout": + f.name = lower + f.logFile = &nopLogFile{os.Stdout} + default: + f.name = s + f.logFile = &realLogFile{s: s} + } + + return nil +} + +func (f *LogFileFlag) Type() string { + return "file" +} + +// Complete is the Cobra compatible completion function for this flag. +func (f *LogFileFlag) Complete(cmd *cobra.Command, args []string, toComplete string) ([]string, cobra.ShellCompDirective) { + return []string{ + "stdout", + "stderr", + }, cobra.ShellCompDirectiveDefault +} diff --git a/libs/flags/log_file_flag_test.go b/libs/flags/log_file_flag_test.go new file mode 100644 index 00000000..3a9df3b4 --- /dev/null +++ b/libs/flags/log_file_flag_test.go @@ -0,0 +1,126 @@ +package flags + +import ( + "os" + "path/filepath" + "testing" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" +) + +func TestLogFileFlagDefault(t *testing.T) { + f := NewLogFileFlag() + assert.Equal(t, os.Stderr, f.Writer()) + assert.Equal(t, "stderr", f.String()) +} + +func TestLogFileFlagSetStdout(t *testing.T) { + var err error + + f := NewLogFileFlag() + err = f.Set("stdout") + require.NoError(t, err) + assert.Equal(t, os.Stdout, f.Writer()) + assert.Equal(t, "stdout", f.String()) + err = f.Set("STDOUT") + require.NoError(t, err) + assert.Equal(t, os.Stdout, f.Writer()) + assert.Equal(t, "stdout", f.String()) +} + +func TestLogFileFlagSetStderr(t *testing.T) { + var err error + + f := NewLogFileFlag() + err = f.Set("stderr") + require.NoError(t, err) + assert.Equal(t, os.Stderr, f.Writer()) + assert.Equal(t, "stderr", f.String()) + err = f.Set("STDERR") + require.NoError(t, err) + assert.Equal(t, os.Stderr, f.Writer()) + assert.Equal(t, "stderr", f.String()) +} + +func TestLogFileFlagSetNewFile(t *testing.T) { + var err error + + // Synthesize path to logfile. + dir := t.TempDir() + path := filepath.Join(dir, "logfile") + + // Configure flag. + f := NewLogFileFlag() + err = f.Set(path) + require.NoError(t, err) + err = f.Open() + require.NoError(t, err) + defer f.Close() + + // Writer must be the underlying file. + w := f.Writer() + file, ok := w.(*os.File) + require.True(t, ok) + assert.Equal(t, path, file.Name()) + + // String must be equal to the path. + assert.Equal(t, path, f.String()) +} + +func TestLogFileFlagSetExistingFile(t *testing.T) { + var err error + + // Synthesize path to logfile. + dir := t.TempDir() + path := filepath.Join(dir, "logfile") + + // Add some contents to temporary file. + file, err := os.Create(path) + require.NoError(t, err) + _, err = file.WriteString("a\n") + require.NoError(t, err) + err = file.Close() + require.NoError(t, err) + + // Configure flag. + f := NewLogFileFlag() + err = f.Set(path) + require.NoError(t, err) + err = f.Open() + require.NoError(t, err) + defer f.Close() + + // Writer must be the underlying file. + w := f.Writer() + file, ok := w.(*os.File) + require.True(t, ok) + assert.Equal(t, path, file.Name()) + + // String must be equal to the path. + assert.Equal(t, path, f.String()) + + // Write more contents. + _, err = w.Write([]byte("b\n")) + require.NoError(t, err) + + // Verify that the contents was appended to the file. + buf, err := os.ReadFile(path) + require.NoError(t, err) + assert.Equal(t, "a\nb\n", string(buf)) +} + +func TestLogFileFlagSetBadPath(t *testing.T) { + var err error + + // Synthesize path that doesn't exist. + dir := t.TempDir() + path := filepath.Join(dir, "invalid/logfile") + + // Configure flag. + f := NewLogFileFlag() + err = f.Set(path) + require.NoError(t, err) + err = f.Open() + assert.Error(t, err) +} diff --git a/libs/flags/log_level_flag.go b/libs/flags/log_level_flag.go new file mode 100644 index 00000000..35850b31 --- /dev/null +++ b/libs/flags/log_level_flag.go @@ -0,0 +1,63 @@ +package flags + +import ( + "fmt" + "strings" + + "github.com/databricks/bricks/libs/log" + "github.com/spf13/cobra" + "golang.org/x/exp/maps" + "golang.org/x/exp/slog" +) + +var levels = map[string]slog.Level{ + "trace": log.LevelTrace, + "debug": log.LevelDebug, + "info": log.LevelInfo, + "warn": log.LevelWarn, + "error": log.LevelError, + "disabled": log.LevelDisabled, +} + +type LogLevelFlag struct { + l slog.Level +} + +func NewLogLevelFlag() LogLevelFlag { + return LogLevelFlag{ + l: log.LevelDisabled, + } +} + +func (f *LogLevelFlag) Level() slog.Level { + return f.l +} + +func (f *LogLevelFlag) String() string { + for name, l := range levels { + if f.l == l { + return name + } + } + + return "(unknown)" +} + +func (f *LogLevelFlag) Set(s string) error { + l, ok := levels[strings.ToLower(s)] + if !ok { + return fmt.Errorf("accepted arguments are %s", strings.Join(maps.Keys(levels), ", ")) + } + + f.l = l + return nil +} + +func (f *LogLevelFlag) Type() string { + return "format" +} + +// Complete is the Cobra compatible completion function for this flag. +func (f *LogLevelFlag) Complete(cmd *cobra.Command, args []string, toComplete string) ([]string, cobra.ShellCompDirective) { + return maps.Keys(levels), cobra.ShellCompDirectiveNoFileComp +} diff --git a/libs/flags/log_level_flag_test.go b/libs/flags/log_level_flag_test.go new file mode 100644 index 00000000..ca54d8a9 --- /dev/null +++ b/libs/flags/log_level_flag_test.go @@ -0,0 +1,29 @@ +package flags + +import ( + "testing" + + "github.com/databricks/bricks/libs/log" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" +) + +func TestLogLevelFlagDefault(t *testing.T) { + f := NewLogLevelFlag() + assert.Equal(t, log.LevelDisabled, f.Level()) + assert.Equal(t, "disabled", f.String()) +} + +func TestLogLevelFlagSetValid(t *testing.T) { + f := NewLogLevelFlag() + err := f.Set("info") + require.NoError(t, err) + assert.Equal(t, log.LevelInfo, f.Level()) + assert.Equal(t, "info", f.String()) +} + +func TestLogLevelFlagSetInvalid(t *testing.T) { + f := NewLogLevelFlag() + err := f.Set("invalid") + assert.ErrorContains(t, err, "accepted arguments are ") +} diff --git a/libs/flags/output.go b/libs/flags/output.go index 1223228f..2c5e3496 100644 --- a/libs/flags/output.go +++ b/libs/flags/output.go @@ -3,6 +3,8 @@ package flags import ( "fmt" "strings" + + "github.com/spf13/cobra" ) // Output controls how the CLI should produce its output. @@ -37,3 +39,11 @@ func (f *Output) Set(s string) error { func (f *Output) Type() string { return "type" } + +// Complete is the Cobra compatible completion function for this flag. +func (f *Output) Complete(cmd *cobra.Command, args []string, toComplete string) ([]string, cobra.ShellCompDirective) { + return []string{ + OutputText.String(), + OutputJSON.String(), + }, cobra.ShellCompDirectiveNoFileComp +} diff --git a/libs/log/context.go b/libs/log/context.go new file mode 100644 index 00000000..7ed1d292 --- /dev/null +++ b/libs/log/context.go @@ -0,0 +1,26 @@ +package log + +import ( + "context" + + "golang.org/x/exp/slog" +) + +type logger int + +var loggerKey logger + +// NewContext returns a new Context that carries the specified logger. +// +// Discussion why this is not part of slog itself: https://github.com/golang/go/issues/58243. +func NewContext(ctx context.Context, logger *slog.Logger) context.Context { + return context.WithValue(ctx, loggerKey, logger) +} + +// FromContext returns the Logger value stored in ctx, if any. +// +// Discussion why this is not part of slog itself: https://github.com/golang/go/issues/58243. +func FromContext(ctx context.Context) (*slog.Logger, bool) { + u, ok := ctx.Value(loggerKey).(*slog.Logger) + return u, ok +} diff --git a/libs/log/levels.go b/libs/log/levels.go new file mode 100644 index 00000000..f6277cf3 --- /dev/null +++ b/libs/log/levels.go @@ -0,0 +1,39 @@ +package log + +import "golang.org/x/exp/slog" + +const ( + LevelTrace slog.Level = -8 + LevelDebug slog.Level = -4 + LevelInfo slog.Level = 0 + LevelWarn slog.Level = 4 + LevelError slog.Level = 8 + + // LevelDisabled means nothing is ever logged (no call site may use this level). + LevelDisabled slog.Level = 16 +) + +// ReplaceLevelAttr rewrites the level attribute to the correct string value. +// This is done because slog doesn't include trace level logging and +// otherwise trace logs show up as `DEBUG-4`. +func ReplaceLevelAttr(groups []string, a slog.Attr) slog.Attr { + if a.Key != slog.LevelKey { + return a + } + + level := a.Value.Any().(slog.Level) + switch { + case level < LevelDebug: + a.Value = slog.StringValue("TRACE") + case level < LevelInfo: + a.Value = slog.StringValue("DEBUG") + case level < LevelWarn: + a.Value = slog.StringValue("INFO") + case level < LevelError: + a.Value = slog.StringValue("WARNING") + default: + a.Value = slog.StringValue("ERROR") + } + + return a +} diff --git a/libs/log/logger.go b/libs/log/logger.go new file mode 100644 index 00000000..80d8782c --- /dev/null +++ b/libs/log/logger.go @@ -0,0 +1,77 @@ +package log + +import ( + "context" + "fmt" + "runtime" + "time" + + "golang.org/x/exp/slog" +) + +// GetLogger returns either the logger configured on the context, +// or the global logger if one isn't defined. +func GetLogger(ctx context.Context) *slog.Logger { + logger, ok := FromContext(ctx) + if !ok { + logger = slog.Default() + } + return logger +} + +// helper function to abstract logging a string message. +func log(logger *slog.Logger, ctx context.Context, level slog.Level, msg string) { + var pcs [1]uintptr + // skip [runtime.Callers, this function, this function's caller]. + runtime.Callers(3, pcs[:]) + r := slog.NewRecord(time.Now(), level, msg, pcs[0]) + if ctx == nil { + ctx = context.Background() + } + _ = logger.Handler().Handle(ctx, r) +} + +// Tracef logs a formatted string using the context-local or global logger. +func Tracef(ctx context.Context, format string, v ...any) { + logger := GetLogger(ctx) + if !logger.Enabled(ctx, LevelTrace) { + return + } + log(logger, ctx, LevelTrace, fmt.Sprintf(format, v...)) +} + +// Debugf logs a formatted string using the context-local or global logger. +func Debugf(ctx context.Context, format string, v ...any) { + logger := GetLogger(ctx) + if !logger.Enabled(ctx, LevelDebug) { + return + } + log(logger, ctx, LevelDebug, fmt.Sprintf(format, v...)) +} + +// Infof logs a formatted string using the context-local or global logger. +func Infof(ctx context.Context, format string, v ...any) { + logger := GetLogger(ctx) + if !logger.Enabled(ctx, LevelInfo) { + return + } + log(logger, ctx, LevelInfo, fmt.Sprintf(format, v...)) +} + +// Warnf logs a formatted string using the context-local or global logger. +func Warnf(ctx context.Context, format string, v ...any) { + logger := GetLogger(ctx) + if !logger.Enabled(ctx, LevelWarn) { + return + } + log(logger, ctx, LevelWarn, fmt.Sprintf(format, v...)) +} + +// Errorf logs a formatted string using the context-local or global logger. +func Errorf(ctx context.Context, format string, v ...any) { + logger := GetLogger(ctx) + if !logger.Enabled(ctx, LevelError) { + return + } + log(logger, ctx, LevelError, fmt.Sprintf(format, v...)) +} diff --git a/libs/log/sdk.go b/libs/log/sdk.go new file mode 100644 index 00000000..975f83aa --- /dev/null +++ b/libs/log/sdk.go @@ -0,0 +1,89 @@ +package log + +import ( + "context" + "fmt" + "runtime" + "time" + + sdk "github.com/databricks/databricks-sdk-go/logger" + "golang.org/x/exp/slog" +) + +// slogAdapter makes an slog.Logger usable with the Databricks SDK. +type slogAdapter struct{} + +func (s slogAdapter) Enabled(ctx context.Context, level sdk.Level) bool { + logger := GetLogger(ctx) + switch level { + case sdk.LevelTrace: + return logger.Enabled(ctx, LevelTrace) + case sdk.LevelDebug: + return logger.Enabled(ctx, LevelDebug) + case sdk.LevelInfo: + return logger.Enabled(ctx, LevelInfo) + case sdk.LevelWarn: + return logger.Enabled(ctx, LevelWarn) + case sdk.LevelError: + return logger.Enabled(ctx, LevelError) + default: + return true + } +} + +func (s slogAdapter) log(logger *slog.Logger, ctx context.Context, level slog.Level, msg string) { + var pcs [1]uintptr + // skip [runtime.Callers, this function, this function's caller, the caller in the SDK]. + runtime.Callers(4, pcs[:]) + r := slog.NewRecord(time.Now(), level, msg, pcs[0]) + r.AddAttrs(slog.Bool("sdk", true)) + if ctx == nil { + ctx = context.Background() + } + _ = logger.Handler().Handle(ctx, r) +} + +func (s slogAdapter) Tracef(ctx context.Context, format string, v ...any) { + logger := GetLogger(ctx) + if !logger.Enabled(ctx, LevelTrace) { + return + } + s.log(logger, ctx, LevelTrace, fmt.Sprintf(format, v...)) +} + +func (s slogAdapter) Debugf(ctx context.Context, format string, v ...any) { + logger := GetLogger(ctx) + if !logger.Enabled(ctx, LevelDebug) { + return + } + s.log(logger, ctx, LevelDebug, fmt.Sprintf(format, v...)) +} + +func (s slogAdapter) Infof(ctx context.Context, format string, v ...any) { + logger := GetLogger(ctx) + if !logger.Enabled(ctx, LevelInfo) { + return + } + s.log(logger, ctx, LevelInfo, fmt.Sprintf(format, v...)) +} + +func (s slogAdapter) Warnf(ctx context.Context, format string, v ...any) { + logger := GetLogger(ctx) + if !logger.Enabled(ctx, LevelWarn) { + return + } + s.log(logger, ctx, LevelWarn, fmt.Sprintf(format, v...)) +} + +func (s slogAdapter) Errorf(ctx context.Context, format string, v ...any) { + logger := GetLogger(ctx) + if !logger.Enabled(ctx, LevelError) { + return + } + s.log(logger, ctx, LevelError, fmt.Sprintf(format, v...)) +} + +func init() { + // Configure SDK to use this logger. + sdk.DefaultLogger = slogAdapter{} +}