better CLI wrapping & begin using log/slog

README.md

@@ -28,5 +28,6 @@ related things like AWS wrappers or Prometheus helpers.
 Deprecations
 ------------
 
-- `csrf/` - just use SameSite cookies
-- `crypto/pkencryptedstream/` - provides confidentiality, but is malleable (ciphertext is not authenticated). Use Age instead.
+- [net/http/csrf/](net/http/csrf/) - just use SameSite cookies
+- [crypto/pkencryptedstream/](crypto/pkencryptedstream/) - provides confidentiality, but is malleable (ciphertext is not authenticated). Use Age instead.
+- [log/logex/](log/logex/) - use [log/slog](https://go.dev/blog/slog) i.e. the official solution to pain which our package addressed.

app/cli/DEPRECATED.go

@@ -0,0 +1,33 @@
+package cli
+
+import (
+	"context"
+	"log"
+
+	"github.com/function61/gokit/log/logex"
+	"github.com/function61/gokit/os/osutil"
+	"github.com/spf13/cobra"
+)
+
+// below intended to be deprecated soon
+
+func RunnerNoArgs(run func(ctx context.Context, logger *log.Logger) error) func(*cobra.Command, []string) {
+	return func(_ *cobra.Command, _ []string) {
+		logger := logex.StandardLogger()
+
+		osutil.ExitIfError(run(
+			osutil.CancelOnInterruptOrTerminate(logger),
+			logger))
+	}
+}
+
+func Runner(run func(ctx context.Context, args []string, logger *log.Logger) error) func(*cobra.Command, []string) {
+	return func(_ *cobra.Command, args []string) {
+		logger := logex.StandardLogger()
+
+		osutil.ExitIfError(run(
+			osutil.CancelOnInterruptOrTerminate(logger),
+			args,
+			logger))
+	}
+}

app/cli/cobrawrappers.go

@@ -1,32 +1,58 @@
-// Cobra wrappers to wrap awkward API (no exit codes and no built-in "ctrl-c => cancel" support)
+// Making CLI commands have some quality without too much boilerplate.
 package cli
 
 import (
 	"context"
-	"log"
+	"os"
 
-	"github.com/function61/gokit/log/logex"
+	"github.com/function61/gokit/app/dynversion"
 	"github.com/function61/gokit/os/osutil"
 	"github.com/spf13/cobra"
+	"github.com/spf13/pflag"
 )
 
-func RunnerNoArgs(run func(ctx context.Context, logger *log.Logger) error) func(*cobra.Command, []string) {
-	return func(_ *cobra.Command, _ []string) {
-		logger := logex.StandardLogger()
+// wraps the `Execute()` call of the command to inject boilerplate details like `Use`, `Version` and
+// handling of error to `Command.Execute()` (such as flag validation, missing command etc.)
+func Execute(app *cobra.Command) {
+	// dirty to mutate after-the-fact
 
-		osutil.ExitIfError(run(
-			osutil.CancelOnInterruptOrTerminate(logger),
-			logger))
-	}
+	app.Use = os.Args[0]
+	app.Version = dynversion.Version
+	// hide the default "completion" subcommand from polluting UX (it can still be used). https://github.com/spf13/cobra/issues/1507
+	app.CompletionOptions = cobra.CompletionOptions{HiddenDefaultCmd: true}
+
+	// cannot `AddLogLevelControls(app.Flags())` here because it gets confusing if:
+	// a) the root command is not runnable
+	// b) the root command is runnable BUT it doesn't do logging (or there is no debug-level logs to suppress)
+
+	osutil.ExitIfError(app.Execute())
 }
 
-func Runner(run func(ctx context.Context, args []string, logger *log.Logger) error) func(*cobra.Command, []string) {
+// fixes problems of cobra commands' bare run callbacks with regards to application quality:
+// 1. logging not configured
+// 2. no interrupt handling
+// 3. no error handling
+func WrapRun(run func(ctx context.Context, args []string) error) func(*cobra.Command, []string) {
 	return func(_ *cobra.Command, args []string) {
-		logger := logex.StandardLogger()
+		// handle logging
+		configureLogging()
+
+		// handle interrupts
+		ctx := notifyContextInterruptOrTerminate()
 
-		osutil.ExitIfError(run(
-			osutil.CancelOnInterruptOrTerminate(logger),
-			args,
-			logger))
+		// run the actual code (jump from CLI context to higher-level application context)
+		// this can be kinda read as:
+		//  output = logic(input)
+		err := run(ctx, args)
+
+		// handle errors
+		osutil.ExitIfError(err)
 	}
 }
+
+// adds CLI flags that control the logging level
+func AddLogLevelControls(flags *pflag.FlagSet) {
+	flags.BoolVarP(&logLevelVerbose, "verbose", "v", logLevelVerbose, "Include debug-level logs")
+
+	// TODO: maybe add a "quiet" level as well
+}

app/cli/logging.go

@@ -0,0 +1,82 @@
+package cli
+
+import (
+	"log/slog"
+	"os"
+	"time"
+
+	"github.com/lmittmann/tint"
+	"github.com/mattn/go-isatty"
+)
+
+var (
+	logLevelVerbose = false
+	discardAttr     = slog.Attr{} // zero `Attr` means discard
+)
+
+func configureLogging() {
+	logLevel := func() slog.Level {
+		if logLevelVerbose {
+			return slog.LevelDebug
+		} else {
+			return slog.LevelInfo
+		}
+	}()
+
+	addSource := func() bool {
+		if logLevelVerbose {
+			return true
+		} else {
+			return false
+		}
+	}()
+
+	errorStream := os.Stderr
+	errorStreamIsUserTerminal := isatty.IsTerminal(errorStream.Fd())
+
+	logHandler := func() slog.Handler {
+		if errorStreamIsUserTerminal { // output format optimized to looking at from terminal
+			return tint.NewHandler(errorStream, &tint.Options{
+				Level:      logLevel,
+				AddSource:  addSource,
+				TimeFormat: time.TimeOnly, // not using freedom time (`time.Kitchen`)
+				// intentionally not giving `ReplaceAttr` because for terminal we can always include times
+			})
+		} else { // "production" log output
+			logAttrReplacer := timeRemoverAttrReplacer
+			if !logsShouldOmitTime() {
+				logAttrReplacer = nil
+			}
+
+			return slog.NewTextHandler(errorStream, &slog.HandlerOptions{
+				Level:       logLevel,
+				AddSource:   addSource,
+				ReplaceAttr: logAttrReplacer,
+			})
+		}
+	}()
+
+	// expecting the apps to just use the global logger
+	slog.SetDefault(slog.New(logHandler))
+}
+
+// if our logs are redirected to journald or similar which already add timestamps don't add double timestamps
+func logsShouldOmitTime() bool {
+	// "This permits invoked processes to safely detect whether their standard output or standard
+	// error output are connected to the journal."
+	// https://www.freedesktop.org/software/systemd/man/systemd.exec.html#%24JOURNAL_STREAM
+	systemdJournal := os.Getenv("JOURNAL_STREAM") != ""
+
+	// explicitly asked, e.g. set by orchestrator when running in Docker with log redirection taken care of
+	explicitSuppress := os.Getenv("LOGGER_SUPPRESS_TIMESTAMPS") == "1"
+
+	return systemdJournal || explicitSuppress
+}
+
+func timeRemoverAttrReplacer(groups []string, a slog.Attr) slog.Attr {
+	if a.Key == slog.TimeKey {
+		return discardAttr
+	} else {
+		return a
+	}
+}

app/cli/signalnotifycontext.go

@@ -0,0 +1,38 @@
+package cli
+
+import (
+	"context"
+	"log/slog"
+	"os"
+	"os/signal"
+	"syscall"
+)
+
+// same as `signal.NotifyContext()` but logs output when got signal to give useful feedback to user
+// that we have begun teardown. this feedback becomes extremely important if the teardown process
+// takes time or gets stuck.
+func notifyContextInterruptOrTerminate() context.Context {
+	ctx, cancel := context.WithCancel(context.Background())
+
+	// need a buffered channel because the sending side is non-blocking
+	ch := make(chan os.Signal, 1)
+
+	// "The SIGINT signal is sent to a process by its controlling terminal when a user wishes to interrupt the process"
+	// "The SIGTERM signal is sent to a process to request its termination"
+	// "SIGINT is nearly identical to SIGTERM"
+	//     https://en.wikipedia.org/wiki/Signal_(IPC)
+	signal.Notify(ch, syscall.SIGINT, syscall.SIGTERM)
+
+	go func() {
+		slog.Info("STOPPING. (If stuck, send sig again to force exit.)", "signal", <-ch)
+
+		// stop accepting signals on the channel. this undoes the effect of this func,
+		// and thus makes the process terminate on the next received signal (so you can stop
+		// your program if the cleanup code gets stuck)
+		signal.Stop(ch)
+
+		cancel()
+	}()
+
+	return ctx
+}

app/retry/retry.go

@@ -4,7 +4,7 @@ package retry
 import (
 	"context"
 	"fmt"
-	"log"
+	"log/slog"
 	"time"
 
 	"github.com/function61/gokit/app/backoff"
@@ -26,20 +26,28 @@ func Retry(
 			return nil // no error, happy path
 		}
 
-		attemptDuration := time.Since(attemptStarted)
+		errAttemptStructural := &retryAttemptError{
+			attemptError:    errAttempt,
+			attemptDuration: time.Since(attemptStarted),
+			attemptNumber:   attemptNumber,
+		}
 
-		err := fmt.Errorf("attempt %d failed in %s: %s", attemptNumber, attemptDuration, errAttempt.Error())
+		failed(errAttemptStructural)
 
 		select {
 		case <-ctx.Done(): // context canceled? (= deadline exceeded)
-			err = fmt.Errorf("GIVING UP (context timeout): %s", err.Error())
-			failed(err)
-			return err
+			// TODO: what about explicit cancel (not timeout?)
+
+			// not calling `failed()` here because the surfacing of this conclusion error is the
+			// caller's responsibility.
+
+			return &retryAggregateFailed{
+				outcome:     fmt.Errorf("Retry: bailing out (%w)", ctx.Err()),
+				lastAttempt: errAttemptStructural,
+			}
 		case <-time.After(backoffDuration()):
 		}
 
-		failed(err)
-
 		attemptNumber++
 	}
 }
@@ -67,8 +75,54 @@ func IgnoreErrorsWithin(expectErrorsWithin time.Duration, handleError func(error
 }
 
 // creates `Retry()` compatible error handler function that just pushes errors to a logger
-func ErrorsToLogger(logger *log.Logger) func(error) {
+func ErrorsToLogger(logger *slog.Logger) func(error) {
 	return func(err error) {
-		logger.Println(err.Error())
+		logger.Warn("retry attempt failed", "attempt", err)
 	}
 }
+
+type retryAggregateFailed struct {
+	outcome     error // intentionally does not wrap `lastAttempt`
+	lastAttempt error
+}
+
+var _ interface {
+	error
+	slog.LogValuer
+} = (*retryAggregateFailed)(nil)
+
+func (r *retryAggregateFailed) Error() string {
+	return fmt.Sprintf("%v: %v", r.outcome, r.lastAttempt)
+}
+
+func (r *retryAggregateFailed) LogValue() slog.Value {
+	return slog.GroupValue(
+		slog.String("outcome", r.outcome.Error()),
+		slog.Any("last_attempt", r.lastAttempt),
+	)
+}
+
+// this exists mainly to be able to unpack these details in bowels of `ErrorsToLogger()` via `error` type.
+// (to be able to structurally log the details.)
+type retryAttemptError struct {
+	attemptError    error
+	attemptDuration time.Duration
+	attemptNumber   int
+}
+
+var _ interface {
+	error
+	slog.LogValuer
+} = (*retryAttemptError)(nil)
+
+func (r *retryAttemptError) Error() string {
+	return fmt.Sprintf("attempt %d failed (in %s): %v", r.attemptNumber, r.attemptDuration, r.attemptError.Error())
+}
+
+func (r *retryAttemptError) LogValue() slog.Value {
+	return slog.GroupValue(
+		slog.Any("number", r.attemptNumber),
+		slog.Any("error", r.attemptError),
+		slog.Any("duration", r.attemptDuration),
+	)
+}

app/retry/retry_test.go

@@ -3,7 +3,6 @@ package retry
 import (
 	"context"
 	"errors"
-	"regexp"
 	"testing"
 	"time"
 
@@ -52,8 +51,8 @@ func TestSucceedsOnThirdTry(t *testing.T) {
 	assert.Equal(t, attempts, 3)
 	assert.Equal(t, len(receivedErrors), 2)
 	// use regex to work around variable timing ("failed in 270ns")
-	assert.Matches(t, receivedErrors[0].Error(), "attempt 1 failed in .+: fails on first try")
-	assert.Matches(t, receivedErrors[1].Error(), "attempt 2 failed in .+: fails on second as well")
+	assert.Matches(t, receivedErrors[0].Error(), `attempt 1 failed \(in .+\): fails on first try`)
+	assert.Matches(t, receivedErrors[1].Error(), `attempt 2 failed \(in .+\): fails on second as well`)
 }
 
 func TestTakesTooLong(t *testing.T) {
@@ -82,6 +81,6 @@ func TestTakesTooLong(t *testing.T) {
 
 	assert.Equal(t, attempts, 1)
 	assert.Equal(t, len(receivedErrors), 1)
-	assert.Equal(t, regexp.MustCompile(`GIVING UP \(context timeout\): attempt 1 failed in .+: encountered timeout`).MatchString(receivedErrors[0].Error()), true)
-	assert.Equal(t, err.Error(), receivedErrors[0].Error())
+	assert.Matches(t, receivedErrors[0].Error(), `attempt 1 failed \(in .+\): encountered timeout`)
+	assert.Matches(t, err.Error(), `Retry: bailing out \(context deadline exceeded\): attempt 1 failed \(in .+\): encountered timeout`)
 }

go.mod

@@ -24,6 +24,7 @@ require (
 	github.com/golang/protobuf v1.3.2 // indirect
 	github.com/inconshreveable/mousetrap v1.0.1 // indirect
 	github.com/jmespath/go-jmespath v0.0.0-20180206201540-c2b33e8439af // indirect
+	github.com/lmittmann/tint v1.0.5 // indirect
 	github.com/matttproud/golang_protobuf_extensions v1.0.1 // indirect
 	github.com/pkg/errors v0.8.1 // indirect
 	github.com/prometheus/client_model v0.2.0 // indirect

go.sum

@@ -45,6 +45,8 @@ github.com/json-iterator/go v1.1.7/go.mod h1:KdQUCv79m/52Kvf8AW2vK1V8akMuk1QjK/u
 github.com/julienschmidt/httprouter v1.2.0/go.mod h1:SYymIcj16QtmaHHD7aYtjjsJG7VTCxuUUipMqKk8s4w=
 github.com/konsorten/go-windows-terminal-sequences v1.0.1/go.mod h1:T0+1ngSBFLxvqU3pZ+m/2kptfBszLMUkC4ZK/EgS/cQ=
 github.com/kr/logfmt v0.0.0-20140226030751-b84e30acd515/go.mod h1:+0opPa2QZZtGFBFZlji/RkVcI2GknAs/DXo4wKdlNEc=
+github.com/lmittmann/tint v1.0.5 h1:NQclAutOfYsqs2F1Lenue6OoWCajs5wJcP3DfWVpePw=
+github.com/lmittmann/tint v1.0.5/go.mod h1:HIS3gSy7qNwGCj+5oRjAutErFBl4BzdQP6cJZ0NfMwE=
 github.com/mattn/go-isatty v0.0.20 h1:xfD0iDuEKnDkl03q4limB+vH+GxLEtL/jb4xVJSWWEY=
 github.com/mattn/go-isatty v0.0.20/go.mod h1:W+V8PltTTMOvKvAeJH7IuucS94S2C6jfK/D7dTCTo3Y=
 github.com/matttproud/golang_protobuf_extensions v1.0.1 h1:4hp9jkHxhMHkqkrB3Ix0jegS5sx/RkqARlsWZ6pIwiU=