better CLI wrapping & begin using log/slog

Author: joonas-fi

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

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=

os/systemdcli/cli.go

@@ -4,7 +4,6 @@ package systemdcli
 import (
 	"context"
 	"fmt"
-	"log"
 	"os"
 	"os/exec"
 
@@ -40,7 +39,7 @@ func Entrypoint(serviceName string, makeAdditionalCommands func(string) []*cobra
 		Use:   "start",
 		Short: "Start the service",
 		Args:  cobra.NoArgs,
-		Run: cli.RunnerNoArgs(func(ctx context.Context, _ *log.Logger) error {
+		Run: cli.WrapRun(func(ctx context.Context, _ []string) error {
 			return runSystemctlVerb(ctx, "start")
 		}),
 	})
@@ -49,7 +48,7 @@ func Entrypoint(serviceName string, makeAdditionalCommands func(string) []*cobra
 		Use:   "stop",
 		Short: "Stop the service",
 		Args:  cobra.NoArgs,
-		Run: cli.RunnerNoArgs(func(ctx context.Context, _ *log.Logger) error {
+		Run: cli.WrapRun(func(ctx context.Context, _ []string) error {
 			return runSystemctlVerb(ctx, "stop")
 		}),
 	})
@@ -58,7 +57,7 @@ func Entrypoint(serviceName string, makeAdditionalCommands func(string) []*cobra
 		Use:   "restart",
 		Short: "Restart the service",
 		Args:  cobra.NoArgs,
-		Run: cli.RunnerNoArgs(func(ctx context.Context, _ *log.Logger) error {
+		Run: cli.WrapRun(func(ctx context.Context, _ []string) error {
 			return runSystemctlVerb(ctx, "restart")
 		}),
 	})
@@ -67,7 +66,7 @@ func Entrypoint(serviceName string, makeAdditionalCommands func(string) []*cobra
 		Use:   "status",
 		Short: "Show status of the service",
 		Args:  cobra.NoArgs,
-		Run: cli.RunnerNoArgs(func(ctx context.Context, _ *log.Logger) error {
+		Run: cli.WrapRun(func(ctx context.Context, _ []string) error {
 			translateNonError := func(err error) error {
 				if err != nil {
 					// LSB dictates that successful status show of non-running program must return 3:
@@ -90,7 +89,7 @@ func Entrypoint(serviceName string, makeAdditionalCommands func(string) []*cobra
 		Use:   "logs",
 		Short: "Get logs for the service",
 		Args:  cobra.NoArgs,
-		Run: cli.RunnerNoArgs(func(ctx context.Context, _ *log.Logger) error {
+		Run: cli.WrapRun(func(ctx context.Context, _ []string) error {
 			//nolint:gosec // ok, is expected to not be user input.
 			logsCmd := exec.CommandContext(ctx, "journalctl", "--unit="+serviceName)
 			logsCmd.Stdout = os.Stdout
@@ -109,7 +108,7 @@ func WithInstallAndUninstallCommands(makeSvc func(string) (*systemdinstaller.Ser
 				Use:   "install",
 				Short: "Installs the background service",
 				Args:  cobra.NoArgs,
-				Run: cli.RunnerNoArgs(func(ctx context.Context, _ *log.Logger) error {
+				Run: cli.WrapRun(func(_ context.Context, _ []string) error {
 					svc, err := makeSvc(serviceName)
 					if err != nil {
 						return err