refactor(coder/cli): extract BuildLogger to clilog

coder · johnstcn · Dec 19, 2023 · Dec 19, 2023 · Dec 19, 2023 · Dec 19, 2023
commit 1377d010bf1581899a110c343760a81665a8f2ca
diff --git a/cli/clilog/clilog.go b/cli/clilog/clilog.go
@@ -0,0 +1,192 @@
+package clilog
+
+import (
+	"context"
+	"fmt"
+	"io"
+	"os"
+	"regexp"
+	"strings"
+
+	"golang.org/x/xerrors"
+
+	"cdr.dev/slog"
+	"cdr.dev/slog/sloggers/sloghuman"
+	"cdr.dev/slog/sloggers/slogjson"
+	"cdr.dev/slog/sloggers/slogstackdriver"
+	"github.com/coder/coder/v2/cli/clibase"
+	"github.com/coder/coder/v2/coderd/tracing"
+	"github.com/coder/coder/v2/codersdk"
+)
+
+type Option func(*Builder)
+type Builder struct {
+	Filter      []string
+	Human       string
+	JSON        string
+	Stackdriver string
+	Trace       bool
+	Verbose     bool
+}
+
+func New() *Builder {
+	return &Builder{
+		Human:  "/dev/stderr",
+		Filter: []string{},
+	}
+}
+
+func (b *Builder) WithFilter(filters ...string) *Builder {
+	b.Filter = filters
+	return b
+}
+
+func (b *Builder) WithHuman(loc string) *Builder {
+	b.Human = loc
+	return b
+}
+
+func (b *Builder) WithJSON(loc string) *Builder {
+	b.JSON = loc
+	return b
+}
+
+func (b *Builder) WithStackdriver(loc string) *Builder {
+	b.Stackdriver = loc
+	return b
+}
+
+func (b *Builder) WithTrace() *Builder {
+	b.Trace = true
+	return b
+
+}
+func (b *Builder) WithVerbose() *Builder {
+	b.Verbose = true
+	return b
+}
+
+func (b *Builder) FromDeploymentValues(vals *codersdk.DeploymentValues) *Builder {
+	b.Filter = vals.Logging.Filter.Value()
+	b.Human = vals.Logging.Human.Value()
+	b.JSON = vals.Logging.JSON.Value()
+	b.Stackdriver = vals.Logging.Stackdriver.Value()
+	b.Trace = vals.Trace.Enable.Value()
+	b.Verbose = vals.Verbose.Value()
+	return b
+}
+
+func (b *Builder) Build(inv *clibase.Invocation) (slog.Logger, func(), error) {
+	var (
+		sinks   = []slog.Sink{}
+		closers = []func() error{}
+	)
+
+	addSinkIfProvided := func(sinkFn func(io.Writer) slog.Sink, loc string) error {
+		switch loc {
+		case "":
+
+		case "/dev/stdout":
+			sinks = append(sinks, sinkFn(inv.Stdout))
+
+		case "/dev/stderr":
+			sinks = append(sinks, sinkFn(inv.Stderr))
+
+		default:
+			fi, err := os.OpenFile(loc, os.O_WRONLY|os.O_CREATE|os.O_APPEND, 0o644)
+			if err != nil {
+				return xerrors.Errorf("open log file %q: %w", loc, err)
+			}
+			closers = append(closers, fi.Close)
+			sinks = append(sinks, sinkFn(fi))
+		}
+		return nil
+	}
+
+	err := addSinkIfProvided(sloghuman.Sink, b.Human)
+	if err != nil {
+		return slog.Logger{}, nil, xerrors.Errorf("add human sink: %w", err)
+	}
+	err = addSinkIfProvided(slogjson.Sink, b.JSON)
+	if err != nil {
+		return slog.Logger{}, nil, xerrors.Errorf("add json sink: %w", err)
+	}
+	err = addSinkIfProvided(slogstackdriver.Sink, b.Stackdriver)
+	if err != nil {
+		return slog.Logger{}, nil, xerrors.Errorf("add stackdriver sink: %w", err)
+	}
+
+	if b.Trace {
+		sinks = append(sinks, tracing.SlogSink{})
+	}
+
+	// User should log to null device if they don't want logs.
+	if len(sinks) == 0 {
+		return slog.Logger{}, nil, xerrors.New("no loggers provided")
+	}
+
+	filter := &debugFilterSink{next: sinks}
+
+	err = filter.compile(b.Filter)
+	if err != nil {
+		return slog.Logger{}, nil, xerrors.Errorf("compile filters: %w", err)
+	}
+
+	level := slog.LevelInfo
+	// Debug logging is always enabled if a filter is present.
+	if b.Verbose || filter.re != nil {
+		level = slog.LevelDebug
+	}
+
+	return inv.Logger.AppendSinks(filter).Leveled(level), func() {
+		for _, closer := range closers {
+			_ = closer()
+		}
+	}, nil
+}
+
+var _ slog.Sink = &debugFilterSink{}
+
+type debugFilterSink struct {
+	next []slog.Sink
+	re   *regexp.Regexp
+}
+
+func (f *debugFilterSink) compile(res []string) error {
+	if len(res) == 0 {
+		return nil
+	}
+
+	var reb strings.Builder
+	for i, re := range res {
+		_, _ = fmt.Fprintf(&reb, "(%s)", re)
+		if i != len(res)-1 {
+			_, _ = reb.WriteRune('|')
+		}
+	}
+
+	re, err := regexp.Compile(reb.String())
+	if err != nil {
+		return xerrors.Errorf("compile regex: %w", err)
+	}
+	f.re = re
+	return nil
+}
+
+func (f *debugFilterSink) LogEntry(ctx context.Context, ent slog.SinkEntry) {
+	if ent.Level == slog.LevelDebug {
+		logName := strings.Join(ent.LoggerNames, ".")
+		if f.re != nil && !f.re.MatchString(logName) && !f.re.MatchString(ent.Message) {
+			return
+		}
+	}
+	for _, sink := range f.next {
+		sink.LogEntry(ctx, ent)
+	}
+}
+
+func (f *debugFilterSink) Sync() {
+	for _, sink := range f.next {
+		sink.Sync()
+	}
+}
diff --git a/cli/clilog/clilog_test.go b/cli/clilog/clilog_test.go
@@ -0,0 +1,168 @@
+package clilog_test
+
+import (
+	"encoding/json"
+	"os"
+	"path/filepath"
+	"strings"
+	"testing"
+
+	"github.com/coder/coder/v2/cli/clibase"
+	"github.com/coder/coder/v2/cli/clilog"
+
+	"github.com/stretchr/testify/assert"
+	"github.com/stretchr/testify/require"
+)
+
+func TestBuilder(t *testing.T) {
+	t.Parallel()
+
+	t.Run("WithFilter", func(t *testing.T) {
+		t.Parallel()
+
+		tempFile := filepath.Join(t.TempDir(), "test.log")
+		cmd := &clibase.Cmd{
+			Use: "test",
+			Handler: func(inv *clibase.Invocation) error {
+				logger, closeLog, err := clilog.New().
+					WithFilter("foo", "baz").
+					WithHuman(tempFile).
+					WithVerbose().
+					Build(inv)
+				if err != nil {
+					return err
+				}
+				defer closeLog()
+				logger.Debug(inv.Context(), "foo is not a useful message")
+				logger.Debug(inv.Context(), "bar is also not a useful message")
+				return nil
+			},
+		}
+		err := cmd.Invoke().Run()
+		require.NoError(t, err)
+
+		data, err := os.ReadFile(tempFile)
+		require.NoError(t, err)
+		logs := strings.Split(strings.TrimSpace(string(data)), "\n")
+		if !assert.Len(t, logs, 1) {
+			t.Logf(string(data))
+			t.FailNow()
+		}
+		require.Contains(t, logs[0], "foo is not a useful message")
+	})
+
+	t.Run("WithHuman", func(t *testing.T) {
+		t.Parallel()
+
+		tempFile := filepath.Join(t.TempDir(), "test.log")
+		cmd := &clibase.Cmd{
+			Use: "test",
+			Handler: func(inv *clibase.Invocation) error {
+				logger, closeLog, err := clilog.New().
+					WithHuman(tempFile).
+					Build(inv)
+				if err != nil {
+					return err
+				}
+				defer closeLog()
+				logger.Debug(inv.Context(), "foo is not a useful message")
+				logger.Info(inv.Context(), "bar is also not a useful message")
+				return nil
+			},
+		}
+		err := cmd.Invoke().Run()
+		require.NoError(t, err)
+
+		data, err := os.ReadFile(tempFile)
+		require.NoError(t, err)
+		logs := strings.Split(strings.TrimSpace(string(data)), "\n")
+		if !assert.Len(t, logs, 1) {
+			t.Logf(string(data))
+			t.FailNow()
+		}
+		require.Contains(t, logs[0], "bar is also not a useful message")
+	})
+
+	t.Run("WithJSON", func(t *testing.T) {
+		t.Parallel()
+
+		tempFile := filepath.Join(t.TempDir(), "test.log")
+		cmd := &clibase.Cmd{
+			Use: "test",
+			Handler: func(inv *clibase.Invocation) error {
+				logger, closeLog, err := clilog.New().
+					WithJSON(tempFile).
+					Build(inv)
+				if err != nil {
+					return err
+				}
+				defer closeLog()
+				logger.Debug(inv.Context(), "foo is not a useful message")
+				logger.Info(inv.Context(), "bar is also not a useful message")
+				return nil
+			},
+		}
+		err := cmd.Invoke().Run()
+		require.NoError(t, err)
+
+		data, err := os.ReadFile(tempFile)
+		require.NoError(t, err)
+		logs := strings.Split(strings.TrimSpace(string(data)), "\n")
+		if !assert.Len(t, logs, 1) {
+			t.Logf(string(data))
+			t.FailNow()
+		}
+		require.Contains(t, logs[0], "bar")
+		var entry struct {
+			Level   string `json:"level"`
+			Message string `json:"msg"`
+		}
+
+		err = json.NewDecoder(strings.NewReader(logs[0])).Decode(&entry)
+		require.NoError(t, err)
+		require.Equal(t, "INFO", entry.Level)
+		require.Equal(t, "bar is also not a useful message", entry.Message)
+	})
+
+	t.Run("WithStackdriver", func(t *testing.T) {
+		t.Parallel()
+
+		tempFile := filepath.Join(t.TempDir(), "test.log")
+		cmd := &clibase.Cmd{
+			Use: "test",
+			Handler: func(inv *clibase.Invocation) error {
+				logger, closeLog, err := clilog.New().
+					WithStackdriver(tempFile).
+					Build(inv)
+				if err != nil {
+					return err
+				}
+				defer closeLog()
+				logger.Debug(inv.Context(), "foo is not a useful message")
+				logger.Info(inv.Context(), "bar is also not a useful message")
+				return nil
+			},
+		}
+		err := cmd.Invoke().Run()
+		require.NoError(t, err)
+
+		data, err := os.ReadFile(tempFile)
+		require.NoError(t, err)
+		logs := strings.Split(strings.TrimSpace(string(data)), "\n")
+		if !assert.Len(t, logs, 1) {
+			t.Logf(string(data))
+			t.FailNow()
+		}
+		require.Contains(t, logs[0], "bar is also not a useful message")
+
+		var entry struct {
+			Severity string `json:"severity"`
+			Message  string `json:"message"`
+		}
+
+		err = json.NewDecoder(strings.NewReader(logs[0])).Decode(&entry)
+		require.NoError(t, err)
+		require.Equal(t, "INFO", entry.Severity)
+		require.Equal(t, "bar is also not a useful message", entry.Message)
+	})
+}