fix(enterprise/cli): add CODER_PROVISIONER_DAEMON_LOG_* options (#11279)

- Extracts cli.BuildLogger to clilog package
- Updates existing usage of cli.BuildLogger and removes it
- Use clilog to initialize provisionerd logger
This commit is contained in:
Cian Johnston 2023-12-19 16:49:50 +00:00 committed by GitHub
parent 7c4fbe5bae
commit d2d7628522
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
8 changed files with 587 additions and 128 deletions

211
cli/clilog/clilog.go Normal file
View File

@ -0,0 +1,211 @@
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)
Builder struct {
Filter []string
Human string
JSON string
Stackdriver string
Trace bool
Verbose bool
}
)
func New(opts ...Option) *Builder {
b := &Builder{}
for _, opt := range opts {
opt(b)
}
return b
}
func WithFilter(filters ...string) Option {
return func(b *Builder) {
b.Filter = filters
}
}
func WithHuman(loc string) Option {
return func(b *Builder) {
b.Human = loc
}
}
func WithJSON(loc string) Option {
return func(b *Builder) {
b.JSON = loc
}
}
func WithStackdriver(loc string) Option {
return func(b *Builder) {
b.Stackdriver = loc
}
}
func WithTrace() Option {
return func(b *Builder) {
b.Trace = true
}
}
func WithVerbose() Option {
return func(b *Builder) {
b.Verbose = true
}
}
func FromDeploymentValues(vals *codersdk.DeploymentValues) Option {
return func(b *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()
}
}
func (b *Builder) Build(inv *clibase.Invocation) (log slog.Logger, closeLog func(), err error) {
var (
sinks = []slog.Sink{}
closers = []func() error{}
)
defer func() {
if err != nil {
for _, closer := range closers {
_ = closer()
}
}
}()
noopClose := func() {}
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{}, noopClose, xerrors.Errorf("add human sink: %w", err)
}
err = addSinkIfProvided(slogjson.Sink, b.JSON)
if err != nil {
return slog.Logger{}, noopClose, xerrors.Errorf("add json sink: %w", err)
}
err = addSinkIfProvided(slogstackdriver.Sink, b.Stackdriver)
if err != nil {
return slog.Logger{}, noopClose, 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{}, noopClose, xerrors.New("no loggers provided, use /dev/null to disable logging")
}
filter := &debugFilterSink{next: sinks}
err = filter.compile(b.Filter)
if err != nil {
return slog.Logger{}, noopClose, 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()
}
}

243
cli/clilog/clilog_test.go Normal file
View File

@ -0,0 +1,243 @@
package clilog_test
import (
"encoding/json"
"io/fs"
"os"
"path/filepath"
"strings"
"testing"
"github.com/coder/coder/v2/cli/clibase"
"github.com/coder/coder/v2/cli/clilog"
"github.com/coder/coder/v2/coderd/coderdtest"
"github.com/coder/coder/v2/codersdk"
"github.com/stretchr/testify/assert"
"github.com/stretchr/testify/require"
)
func TestBuilder(t *testing.T) {
t.Parallel()
t.Run("NoConfiguration", func(t *testing.T) {
t.Parallel()
cmd := &clibase.Cmd{
Use: "test",
Handler: testHandler(t),
}
err := cmd.Invoke().Run()
require.ErrorContains(t, err, "no loggers provided, use /dev/null to disable logging")
})
t.Run("Verbose", func(t *testing.T) {
t.Parallel()
tempFile := filepath.Join(t.TempDir(), "test.log")
cmd := &clibase.Cmd{
Use: "test",
Handler: testHandler(t,
clilog.WithHuman(tempFile),
clilog.WithVerbose(),
),
}
err := cmd.Invoke().Run()
require.NoError(t, err)
assertLogs(t, tempFile, debugLog, infoLog, warnLog, filterLog)
})
t.Run("WithFilter", func(t *testing.T) {
t.Parallel()
tempFile := filepath.Join(t.TempDir(), "test.log")
cmd := &clibase.Cmd{
Use: "test",
Handler: testHandler(t,
clilog.WithHuman(tempFile),
// clilog.WithVerbose(), // implicit
clilog.WithFilter("important debug message"),
),
}
err := cmd.Invoke().Run()
require.NoError(t, err)
assertLogs(t, tempFile, infoLog, warnLog, filterLog)
})
t.Run("WithHuman", func(t *testing.T) {
t.Parallel()
tempFile := filepath.Join(t.TempDir(), "test.log")
cmd := &clibase.Cmd{
Use: "test",
Handler: testHandler(t, clilog.WithHuman(tempFile)),
}
err := cmd.Invoke().Run()
require.NoError(t, err)
assertLogs(t, tempFile, infoLog, warnLog)
})
t.Run("WithJSON", func(t *testing.T) {
t.Parallel()
tempFile := filepath.Join(t.TempDir(), "test.log")
cmd := &clibase.Cmd{
Use: "test",
Handler: testHandler(t, clilog.WithJSON(tempFile), clilog.WithVerbose()),
}
err := cmd.Invoke().Run()
require.NoError(t, err)
assertLogsJSON(t, tempFile, debug, debugLog, info, infoLog, warn, warnLog, debug, filterLog)
})
t.Run("FromDeploymentValues", func(t *testing.T) {
t.Parallel()
t.Run("Defaults", func(t *testing.T) {
stdoutPath := filepath.Join(t.TempDir(), "stdout")
stderrPath := filepath.Join(t.TempDir(), "stderr")
stdout, err := os.OpenFile(stdoutPath, os.O_WRONLY|os.O_CREATE|os.O_APPEND, 0o644)
require.NoError(t, err)
t.Cleanup(func() { _ = stdout.Close() })
stderr, err := os.OpenFile(stderrPath, os.O_WRONLY|os.O_CREATE|os.O_APPEND, 0o644)
require.NoError(t, err)
t.Cleanup(func() { _ = stderr.Close() })
// Use the default deployment values.
dv := coderdtest.DeploymentValues(t)
cmd := &clibase.Cmd{
Use: "test",
Handler: testHandler(t, clilog.FromDeploymentValues(dv)),
}
inv := cmd.Invoke()
inv.Stdout = stdout
inv.Stderr = stderr
err = inv.Run()
require.NoError(t, err)
assertLogs(t, stdoutPath, "")
assertLogs(t, stderrPath, infoLog, warnLog)
})
t.Run("Override", func(t *testing.T) {
tempFile := filepath.Join(t.TempDir(), "test.log")
tempJSON := filepath.Join(t.TempDir(), "test.json")
dv := &codersdk.DeploymentValues{
Logging: codersdk.LoggingConfig{
Filter: []string{"foo", "baz"},
Human: clibase.String(tempFile),
JSON: clibase.String(tempJSON),
},
Verbose: true,
Trace: codersdk.TraceConfig{
Enable: true,
},
}
cmd := &clibase.Cmd{
Use: "test",
Handler: testHandler(t, clilog.FromDeploymentValues(dv)),
}
err := cmd.Invoke().Run()
require.NoError(t, err)
assertLogs(t, tempFile, infoLog, warnLog)
assertLogsJSON(t, tempJSON, info, infoLog, warn, warnLog)
})
})
t.Run("NotFound", func(t *testing.T) {
t.Parallel()
tempFile := filepath.Join(t.TempDir(), "doesnotexist", "test.log")
cmd := &clibase.Cmd{
Use: "test",
Handler: func(inv *clibase.Invocation) error {
logger, closeLog, err := clilog.New(
clilog.WithFilter("foo", "baz"),
clilog.WithHuman(tempFile),
clilog.WithVerbose(),
).Build(inv)
if err != nil {
return err
}
defer closeLog()
logger.Error(inv.Context(), "you will never see this")
return nil
},
}
err := cmd.Invoke().Run()
require.ErrorIs(t, err, fs.ErrNotExist)
})
}
var (
debug = "DEBUG"
info = "INFO"
warn = "WARN"
debugLog = "this is a debug message"
infoLog = "this is an info message"
warnLog = "this is a warning message"
filterLog = "this is an important debug message you want to see"
)
func testHandler(t testing.TB, opts ...clilog.Option) clibase.HandlerFunc {
t.Helper()
return func(inv *clibase.Invocation) error {
logger, closeLog, err := clilog.New(opts...).Build(inv)
if err != nil {
return err
}
defer closeLog()
logger.Debug(inv.Context(), debugLog)
logger.Info(inv.Context(), infoLog)
logger.Warn(inv.Context(), warnLog)
logger.Debug(inv.Context(), filterLog)
return nil
}
}
func assertLogs(t testing.TB, path string, expected ...string) {
t.Helper()
data, err := os.ReadFile(path)
require.NoError(t, err)
logs := strings.Split(strings.TrimSpace(string(data)), "\n")
if !assert.Len(t, logs, len(expected)) {
t.Logf(string(data))
t.FailNow()
}
for i, log := range logs {
require.Contains(t, log, expected[i])
}
}
func assertLogsJSON(t testing.TB, path string, levelExpected ...string) {
t.Helper()
data, err := os.ReadFile(path)
require.NoError(t, err)
if len(levelExpected)%2 != 0 {
t.Errorf("levelExpected must be a list of level-message pairs")
return
}
logs := strings.Split(strings.TrimSpace(string(data)), "\n")
if !assert.Len(t, logs, len(levelExpected)/2) {
t.Logf(string(data))
t.FailNow()
}
for i, log := range logs {
var entry struct {
Level string `json:"level"`
Message string `json:"msg"`
}
err := json.NewDecoder(strings.NewReader(log)).Decode(&entry)
require.NoError(t, err)
require.Equal(t, levelExpected[2*i], entry.Level)
require.Equal(t, levelExpected[2*i+1], entry.Message)
}
}

2
cli/clilog/doc.go Normal file
View File

@ -0,0 +1,2 @@
// Package clilog provides a fluent API for configuring structured logging.
package clilog

View File

@ -57,10 +57,9 @@ import (
"cdr.dev/slog"
"cdr.dev/slog/sloggers/sloghuman"
"cdr.dev/slog/sloggers/slogjson"
"cdr.dev/slog/sloggers/slogstackdriver"
"github.com/coder/coder/v2/buildinfo"
"github.com/coder/coder/v2/cli/clibase"
"github.com/coder/coder/v2/cli/clilog"
"github.com/coder/coder/v2/cli/cliui"
"github.com/coder/coder/v2/cli/cliutil"
"github.com/coder/coder/v2/cli/config"
@ -325,7 +324,7 @@ func (r *RootCmd) Server(newAPI func(context.Context, *coderd.Options) (*coderd.
}
PrintLogo(inv, "Coder")
logger, logCloser, err := BuildLogger(inv, vals)
logger, logCloser, err := clilog.New(clilog.FromDeploymentValues(vals)).Build(inv)
if err != nil {
return xerrors.Errorf("make logger: %w", err)
}
@ -2011,121 +2010,6 @@ func IsLocalhost(host string) bool {
return host == "localhost" || host == "127.0.0.1" || host == "::1"
}
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()
}
}
func BuildLogger(inv *clibase.Invocation, cfg *codersdk.DeploymentValues) (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, cfg.Logging.Human.String())
if err != nil {
return slog.Logger{}, nil, xerrors.Errorf("add human sink: %w", err)
}
err = addSinkIfProvided(slogjson.Sink, cfg.Logging.JSON.String())
if err != nil {
return slog.Logger{}, nil, xerrors.Errorf("add json sink: %w", err)
}
err = addSinkIfProvided(slogstackdriver.Sink, cfg.Logging.Stackdriver.String())
if err != nil {
return slog.Logger{}, nil, xerrors.Errorf("add stackdriver sink: %w", err)
}
if cfg.Trace.CaptureLogs {
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(cfg.Logging.Filter.Value())
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 cfg.Verbose || filter.re != nil {
level = slog.LevelDebug
}
return inv.Logger.AppendSinks(filter).Leveled(level), func() {
for _, closer := range closers {
_ = closer()
}
}, nil
}
func ConnectToPostgres(ctx context.Context, logger slog.Logger, driver string, dbURL string) (sqlDB *sql.DB, err error) {
logger.Debug(ctx, "connecting to postgresql")

View File

@ -22,6 +22,43 @@ coder provisionerd start [flags]
Directory to store cached data.
### --log-filter
| | |
| ----------- | ------------------------------------------------- |
| Type | <code>string-array</code> |
| Environment | <code>$CODER_PROVISIONER_DAEMON_LOG_FILTER</code> |
Filter debug logs by matching against a given regex. Use .\* to match all debug logs.
### --log-human
| | |
| ----------- | ---------------------------------------------------- |
| Type | <code>string</code> |
| Environment | <code>$CODER_PROVISIONER_DAEMON_LOGGING_HUMAN</code> |
| Default | <code>/dev/stderr</code> |
Output human-readable logs to a given file.
### --log-json
| | |
| ----------- | --------------------------------------------------- |
| Type | <code>string</code> |
| Environment | <code>$CODER_PROVISIONER_DAEMON_LOGGING_JSON</code> |
Output JSON logs to a given file.
### --log-stackdriver
| | |
| ----------- | ---------------------------------------------------------- |
| Type | <code>string</code> |
| Environment | <code>$CODER_PROVISIONER_DAEMON_LOGGING_STACKDRIVER</code> |
Output Stackdriver compatible logs to a given file.
### --name
| | |
@ -68,3 +105,13 @@ Pre-shared key to authenticate with Coder server.
| Environment | <code>$CODER_PROVISIONERD_TAGS</code> |
Tags to filter provisioner jobs by.
### --verbose
| | |
| ----------- | ---------------------------------------------- |
| Type | <code>bool</code> |
| Environment | <code>$CODER_PROVISIONER_DAEMON_VERBOSE</code> |
| Default | <code>false</code> |
Output debug-level logs.

View File

@ -16,6 +16,7 @@ import (
"cdr.dev/slog/sloggers/sloghuman"
agpl "github.com/coder/coder/v2/cli"
"github.com/coder/coder/v2/cli/clibase"
"github.com/coder/coder/v2/cli/clilog"
"github.com/coder/coder/v2/cli/cliui"
"github.com/coder/coder/v2/cli/cliutil"
"github.com/coder/coder/v2/coderd/database"
@ -55,12 +56,17 @@ func validateProvisionerDaemonName(name string) error {
func (r *RootCmd) provisionerDaemonStart() *clibase.Cmd {
var (
cacheDir string
rawTags []string
pollInterval time.Duration
pollJitter time.Duration
preSharedKey string
name string
cacheDir string
logHuman string
logJSON string
logStackdriver string
logFilter []string
name string
rawTags []string
pollInterval time.Duration
pollJitter time.Duration
preSharedKey string
verbose bool
)
client := new(codersdk.Client)
cmd := &clibase.Cmd{
@ -89,9 +95,23 @@ func (r *RootCmd) provisionerDaemonStart() *clibase.Cmd {
return err
}
logger := slog.Make(sloghuman.Sink(inv.Stderr))
if ok, _ := inv.ParsedFlags().GetBool("verbose"); ok {
logger = logger.Leveled(slog.LevelDebug)
logOpts := []clilog.Option{
clilog.WithFilter(logFilter...),
clilog.WithHuman(logHuman),
clilog.WithJSON(logJSON),
clilog.WithStackdriver(logStackdriver),
}
if verbose {
logOpts = append(logOpts, clilog.WithVerbose())
}
logger, closeLogger, err := clilog.New(logOpts...).Build(inv)
if err != nil {
// Fall back to a basic logger
logger = slog.Make(sloghuman.Sink(inv.Stderr))
logger.Error(ctx, "failed to initialize logger", slog.Error(err))
} else {
defer closeLogger()
}
if len(tags) != 0 {
@ -234,6 +254,41 @@ func (r *RootCmd) provisionerDaemonStart() *clibase.Cmd {
Value: clibase.StringOf(&name),
Default: "",
},
{
Flag: "verbose",
Env: "CODER_PROVISIONER_DAEMON_VERBOSE",
Description: "Output debug-level logs.",
Value: clibase.BoolOf(&verbose),
Default: "false",
},
{
Flag: "log-human",
Env: "CODER_PROVISIONER_DAEMON_LOGGING_HUMAN",
Description: "Output human-readable logs to a given file.",
Value: clibase.StringOf(&logHuman),
Default: "/dev/stderr",
},
{
Flag: "log-json",
Env: "CODER_PROVISIONER_DAEMON_LOGGING_JSON",
Description: "Output JSON logs to a given file.",
Value: clibase.StringOf(&logJSON),
Default: "",
},
{
Flag: "log-stackdriver",
Env: "CODER_PROVISIONER_DAEMON_LOGGING_STACKDRIVER",
Description: "Output Stackdriver compatible logs to a given file.",
Value: clibase.StringOf(&logStackdriver),
Default: "",
},
{
Flag: "log-filter",
Env: "CODER_PROVISIONER_DAEMON_LOG_FILTER",
Description: "Filter debug logs by matching against a given regex. Use .* to match all debug logs.",
Value: clibase.StringArrayOf(&logFilter),
Default: "",
},
}
return cmd

View File

@ -23,6 +23,7 @@ import (
"cdr.dev/slog"
"github.com/coder/coder/v2/cli"
"github.com/coder/coder/v2/cli/clibase"
"github.com/coder/coder/v2/cli/clilog"
"github.com/coder/coder/v2/cli/cliui"
"github.com/coder/coder/v2/coderd"
"github.com/coder/coder/v2/coderd/httpapi"
@ -121,7 +122,7 @@ func (r *RootCmd) proxyServer() *clibase.Cmd {
go cli.DumpHandler(ctx)
cli.PrintLogo(inv, "Coder Workspace Proxy")
logger, logCloser, err := cli.BuildLogger(inv, cfg)
logger, logCloser, err := clilog.New(clilog.FromDeploymentValues(cfg)).Build(inv)
if err != nil {
return xerrors.Errorf("make logger: %w", err)
}

View File

@ -9,6 +9,19 @@ OPTIONS:
-c, --cache-dir string, $CODER_CACHE_DIRECTORY (default: [cache dir])
Directory to store cached data.
--log-filter string-array, $CODER_PROVISIONER_DAEMON_LOG_FILTER
Filter debug logs by matching against a given regex. Use .* to match
all debug logs.
--log-human string, $CODER_PROVISIONER_DAEMON_LOGGING_HUMAN (default: /dev/stderr)
Output human-readable logs to a given file.
--log-json string, $CODER_PROVISIONER_DAEMON_LOGGING_JSON
Output JSON logs to a given file.
--log-stackdriver string, $CODER_PROVISIONER_DAEMON_LOGGING_STACKDRIVER
Output Stackdriver compatible logs to a given file.
--name string, $CODER_PROVISIONER_DAEMON_NAME
Name of this provisioner daemon. Defaults to the current hostname
without FQDN.
@ -25,5 +38,8 @@ OPTIONS:
-t, --tag string-array, $CODER_PROVISIONERD_TAGS
Tags to filter provisioner jobs by.
--verbose bool, $CODER_PROVISIONER_DAEMON_VERBOSE (default: false)
Output debug-level logs.
———
Run `coder --help` for a list of global options.