From e42cede351ad1a2618a7574991c27b670d8bc102 Mon Sep 17 00:00:00 2001 From: Matt Loberg Date: Wed, 20 Mar 2024 13:53:51 -0500 Subject: [PATCH] refactor(logging)!: switch to slog for logging Go now includes a nice way to do structured logs, including JSON. Use that instead of a third party module. BREAKING CHANGE: log format will change a little bit --- config.go | 26 +++++++++++++ go.mod | 1 - go.sum | 6 --- logger.go | 40 ++++++++++++++++++++ logger_test.go | 37 ++++++++++++++++++ main.go | 101 +++++++++++++++++++++++-------------------------- utils.go | 14 ++++--- utils_test.go | 43 +++++++++------------ 8 files changed, 177 insertions(+), 91 deletions(-) create mode 100644 logger.go create mode 100644 logger_test.go diff --git a/config.go b/config.go index 5da52d6..cc5b088 100644 --- a/config.go +++ b/config.go @@ -2,6 +2,8 @@ package main import ( "fmt" + "log/slog" + "os" ) type Config struct { @@ -10,6 +12,30 @@ type Config struct { Region string } +// NewFromEnv creates a new Config from environment variables and defaults +func NewFromEnv() *Config { + cfg := &Config{ + Service: os.Getenv("SERVICE_NAME"), + Environment: os.Getenv("SERVICE_ENV"), + Region: os.Getenv("AWS_REGION"), + } + + if cfg.Service == "" { + slog.Warn("SERVICE_NAME is not set, will not load service values") + } + + if cfg.Environment == "" { + slog.Warn("SERVICE_ENV is not set, defaulting to dev") + cfg.Environment = "dev" + } + + if cfg.Region == "" { + cfg.Region = "us-east-1" + } + + return cfg +} + // ConsulPaths returns the paths from Consul to load func (c *Config) ConsulPaths() []string { paths := []string{ diff --git a/go.mod b/go.mod index 5a22387..2f2dae4 100644 --- a/go.mod +++ b/go.mod @@ -9,7 +9,6 @@ require ( github.com/hashicorp/vault/api v1.12.0 github.com/hashicorp/vault/api/auth/aws v0.6.0 github.com/hashicorp/vault/api/auth/kubernetes v0.6.0 - github.com/rs/zerolog v1.32.0 github.com/samber/lo v1.39.0 github.com/stretchr/testify v1.8.4 ) diff --git a/go.sum b/go.sum index ab34df4..c98e3b7 100644 --- a/go.sum +++ b/go.sum @@ -49,7 +49,6 @@ github.com/cenkalti/backoff/v3 v3.0.0/go.mod h1:cIeZDE3IrqwwJl6VUwCN6trj1oXrTS4r github.com/cespare/xxhash/v2 v2.1.1/go.mod h1:VGX0DQ3Q6kWi7AoAeZDth3/j3BFtOZR5XLFGgcrjCOs= github.com/circonus-labs/circonus-gometrics v2.3.1+incompatible/go.mod h1:nmEj6Dob7S7YxXgwXpfOuvO54S+tGdZdw9fuRZt25Ag= github.com/circonus-labs/circonusllhist v0.1.3/go.mod h1:kMXHVDlOchFAehlya5ePtbp5jckzBHf4XRpQvBOLI+I= -github.com/coreos/go-systemd/v22 v22.5.0/go.mod h1:Y58oyj3AT4RCenI/lSvhwexgC+NSVTIJ3seZv2GcEnc= github.com/creack/pty v1.1.9/go.mod h1:oKZEueFk5CKHvIhNR5MUki03XCEU+Q6VDXinZuGJ33E= github.com/davecgh/go-spew v1.1.0/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38= github.com/davecgh/go-spew v1.1.1/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38= @@ -70,7 +69,6 @@ github.com/go-sql-driver/mysql v1.5.0/go.mod h1:DCzpHaOWr8IXmIStZouvnhqoel9Qv2LB github.com/go-stack/stack v1.8.0/go.mod h1:v0f6uXyyMGvRgIKkXu+yp6POWl0qKG85gN/melR3HDY= github.com/go-test/deep v1.0.2 h1:onZX1rnHT3Wv6cqNgYyFOOlgVKJrksuCMCRvJStbMYw= github.com/go-test/deep v1.0.2/go.mod h1:wGDj63lr65AM2AQyKZd/NYHGb0R+1RLqB8NKt3aSFNA= -github.com/godbus/dbus/v5 v5.0.4/go.mod h1:xhWf0FNVPg57R7Z0UbKHbJfkEywrmjJnf7w5xrFpKfA= github.com/gogo/protobuf v1.1.1/go.mod h1:r8qH/GZQm5c6nD/R0oafs1akxWv10x8SbQlK7atdtwQ= github.com/golang/protobuf v1.2.0/go.mod h1:6lQm79b+lXiMfvg/cZm0SGofjICqVBUtrP5yJMmIC1U= github.com/golang/protobuf v1.3.1/go.mod h1:6lQm79b+lXiMfvg/cZm0SGofjICqVBUtrP5yJMmIC1U= @@ -226,9 +224,6 @@ github.com/prometheus/procfs v0.0.2/go.mod h1:TjEm7ze935MbeOT/UhFTIMYKhuLP4wbCsT github.com/prometheus/procfs v0.0.8/go.mod h1:7Qr8sr6344vo1JqZ6HhLceV9o3AJ1Ff+GxbHq6oeK9A= github.com/rogpeppe/go-internal v1.6.1 h1:/FiVV8dS/e+YqF2JvO3yXRFbBLTIuSDkuC7aBOAvL+k= github.com/rogpeppe/go-internal v1.6.1/go.mod h1:xXDCJY+GAPziupqXw64V24skbSoqbTEfhy4qGm1nDQc= -github.com/rs/xid v1.5.0/go.mod h1:trrq9SKmegXys3aeAKXMUTdJsYXVwGY3RLcfgqegfbg= -github.com/rs/zerolog v1.32.0 h1:keLypqrlIjaFsbmJOBdB/qvyF8KEtCWHwobLp5l/mQ0= -github.com/rs/zerolog v1.32.0/go.mod h1:/7mN4D5sKwJLZQ2b/znpjC3/GQWY/xaDXUM0kKWRHss= github.com/ryanuber/columnize v0.0.0-20160712163229-9b3edd62028f/go.mod h1:sm1tb6uqfes/u+d4ooFouqFdy9/2g9QGwK3SQygK0Ts= github.com/ryanuber/columnize v2.1.0+incompatible/go.mod h1:sm1tb6uqfes/u+d4ooFouqFdy9/2g9QGwK3SQygK0Ts= github.com/ryanuber/go-glob v1.0.0 h1:iQh3xXAumdQ+4Ufa5b25cRpC5TYKlno6hsv6Cb3pkBk= @@ -318,7 +313,6 @@ golang.org/x/sys v0.0.0-20220811171246-fbc7d0a398ab/go.mod h1:oPkhp1MJrh7nUepCBc golang.org/x/sys v0.5.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/sys v0.6.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/sys v0.8.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= -golang.org/x/sys v0.12.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/sys v0.13.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/sys v0.15.0 h1:h48lPFYpsTvQJZF4EKyI4aLHaev3CxivZmv7yZig9pc= golang.org/x/sys v0.15.0/go.mod h1:/VUhepiaJMQUp4+oa/7Zr1D23ma6VTLIYjOOTFZPUcA= diff --git a/logger.go b/logger.go new file mode 100644 index 0000000..fe5ebd2 --- /dev/null +++ b/logger.go @@ -0,0 +1,40 @@ +package main + +import "log/slog" + +// structuredError is an error that can be logged with additional data +type structuredError struct { + err error + args []any +} + +// NewStructuredError returns a new structure error that will be logged with additional data +func serror(err error, args ...any) *structuredError { + return &structuredError{err: err, args: args} +} + +func (e *structuredError) Error() string { + return e.err.Error() +} + +func (e *structuredError) Unwrap() error { + return e.err +} + +// LogValue returns a structured log value for use with slog +func (e structuredError) LogValue() slog.Value { + args := make([]slog.Attr, 0, (len(e.args)/2)+1) + args = append(args, slog.String("message", e.Error())) + + var c interface{} + for _, a := range e.args { + if c == nil { + c = a + continue + } + args = append(args, slog.Any(c.(string), a)) + c = nil + } + + return slog.GroupValue(args...) +} diff --git a/logger_test.go b/logger_test.go new file mode 100644 index 0000000..e3c69d6 --- /dev/null +++ b/logger_test.go @@ -0,0 +1,37 @@ +package main + +import ( + "bytes" + "fmt" + "log/slog" + "os" + "testing" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" +) + +func TestStructuredError(t *testing.T) { + wrapped := fmt.Errorf("test error: %w", os.ErrNotExist) + err := serror(wrapped, "foo", "bar") + + require.ErrorContains(t, err, "test error") + require.ErrorIs(t, err, os.ErrNotExist) + + l, log := testLogger() + l.Error("test", "error", err) + assert.Contains(t, log.String(), `"error":{"message":"test error: file does not exist","foo":"bar"}`) +} + +func testLogger() (*slog.Logger, *bytes.Buffer) { + log := &bytes.Buffer{} + return slog.New(slog.NewJSONHandler(log, &slog.HandlerOptions{ + Level: slog.LevelDebug, + ReplaceAttr: func(_ []string, a slog.Attr) slog.Attr { + if a.Key == "time" { + a.Value = slog.StringValue("test-time") + } + return a + }, + })), log +} diff --git a/main.go b/main.go index 3368157..4f8d7f3 100644 --- a/main.go +++ b/main.go @@ -3,85 +3,76 @@ package main import ( "context" "errors" + "fmt" + "log/slog" "os" "os/exec" "runtime" "strconv" "strings" - - "github.com/rs/zerolog" - "github.com/rs/zerolog/log" ) +var logLevel = new(slog.LevelVar) + func main() { ctx := context.Background() - zerolog.SetGlobalLevel(zerolog.InfoLevel) + logger := slog.New(slog.NewJSONHandler(os.Stderr, &slog.HandlerOptions{Level: logLevel})) + slog.SetDefault(logger) if v, ok := os.LookupEnv("DEBUG_BOOTSTRAP"); ok && v != "false" { - zerolog.SetGlobalLevel(zerolog.DebugLevel) - } - - cfg := &Config{ - Service: os.Getenv("SERVICE_NAME"), - Environment: os.Getenv("SERVICE_ENV"), - Region: os.Getenv("AWS_REGION"), + logLevel.Set(slog.LevelDebug) } - if cfg.Service == "" { - log.Warn().Msg("SERVICE_NAME is not set, will not load service values") - } - - if cfg.Environment == "" { - log.Warn().Msg("SERVICE_ENV is not set, defaulting to dev") - cfg.Environment = "dev" - } - - if cfg.Region == "" { - cfg.Region = "us-east-1" - } - - logger := log.With(). - Str("env", cfg.Environment). - Str("service", cfg.Service). - Str("region", cfg.Region). - Logger() + cfg := NewFromEnv() + logger = logger.With("env", cfg.Environment, "service", cfg.Service, "region", cfg.Region) + slog.SetDefault(logger) if len(os.Args) < 2 { - logger.Fatal().Msg("Missing command") + logger.ErrorContext(ctx, "Missing command") + os.Exit(1) } env := NewEnvMap() - if addr := os.Getenv("CONSUL_ADDR"); addr != "" { - env.Merge(loadConsul(addr, cfg, logger)) + c, err := loadConsul(ctx, addr, cfg, logger) + if err != nil { + logger.ErrorContext(ctx, "Could not load values from Consul", "error", err) + os.Exit(1) + } + env.Merge(c) } else { - logger.Warn().Msg("Not loading values from Consul. CONSUL_ADDR is not set") + logger.WarnContext(ctx, "Not loading values from Consul. CONSUL_ADDR is not set") } if addr := os.Getenv("VAULT_ADDR"); addr != "" { - env.Merge(loadVault(ctx, addr, cfg, logger)) + v, err := loadVault(ctx, addr, cfg, logger) + if err != nil { + logger.ErrorContext(ctx, "Could not load values from Vault", "error", err) + os.Exit(1) + } + env.Merge(v) } else { - logger.Warn().Msg("Not loading values from Vault. VAULT_ADDR is not set") + logger.WarnContext(ctx, "Not loading values from Vault. VAULT_ADDR is not set") } pwd, err := os.Getwd() if err != nil { - logger.Warn().Err(err).Msg("Cannot determine PWD") + logger.WarnContext(ctx, "Cannot determine PWD", "error", err) } env.Add("PWD", pwd) env.Add("AWS_REGION", cfg.Region) env.Add("SERVICE_ENV", cfg.Environment) env.Add("PROCESSOR_COUNT", strconv.Itoa(runtime.NumCPU())) - os.Exit(run(os.Args[1], os.Args[2:], env.Environ(), logger)) + os.Exit(run(ctx, os.Args[1], os.Args[2:], env.Environ(), logger)) } -func loadConsul(addr string, c *Config, l zerolog.Logger) Dict { - l.Debug().Msg("Loading values from Consul") +func loadConsul(ctx context.Context, addr string, c *Config, l *slog.Logger) (Dict, error) { + l.Debug("Loading values from Consul") client, err := NewConsul(addr) if err != nil { - l.Fatal().Err(err).Str("addr", addr).Msg("Could not connect to Consul") + return nil, serror(fmt.Errorf("Could not connect to Consul: %w", err), "addr", addr) } paths := c.ConsulPaths() @@ -89,20 +80,20 @@ func loadConsul(addr string, c *Config, l zerolog.Logger) Dict { paths = append(paths, strings.Split(p, ",")...) } - return loadValues(client, l, paths) + return loadValues(ctx, client, l, paths) } -func loadVault(ctx context.Context, addr string, c *Config, l zerolog.Logger) Dict { - l.Debug().Msg("Loading values from Vault") +func loadVault(ctx context.Context, addr string, c *Config, l *slog.Logger) (Dict, error) { + l.DebugContext(ctx, "Loading values from Vault") client, err := NewVault(addr, c.Region) if err != nil { - l.Fatal().Err(err).Str("addr", addr).Msg("Could not connect to Vault") + return nil, serror(fmt.Errorf("Could not connect to Vault: %w", err), "addr", addr) } token, err := vaultToken(ctx) if err != nil { - l.Fatal().Err(err).Msg("Could not get Vault token") + return nil, fmt.Errorf("Could not get Vault token: %w", err) } role := os.Getenv("VAULT_ROLE") @@ -112,12 +103,12 @@ func loadVault(ctx context.Context, addr string, c *Config, l zerolog.Logger) Di auth, err := client.Authenticate(ctx, token, role) if err != nil { - l.Fatal().Err(err).Msg("Could not authenticate Vault") + return nil, fmt.Errorf("Could not authenticate Vault: %w", err) } if auth == "" { - l.Warn().Msg("Not loading values from Vault. Unable to authenticate Vault") - return make(Dict) + l.WarnContext(ctx, "Not loading values from Vault. Unable to authenticate Vault") + return make(Dict), nil } paths := c.VaultPaths() @@ -125,20 +116,21 @@ func loadVault(ctx context.Context, addr string, c *Config, l zerolog.Logger) Di paths = append(paths, strings.Split(p, ",")...) } - values := loadValues(client, l, paths) + values, err := loadValues(ctx, client, l, paths) values["VAULT_TOKEN"] = auth - return values + return values, err } -func run(name string, args, env []string, l zerolog.Logger) int { - cmd := exec.Command(name, args...) //nolint:gosec +func run(ctx context.Context, name string, args, env []string, l *slog.Logger) int { + cmd := exec.CommandContext(ctx, name, args...) //nolint:gosec cmd.Env = append(os.Environ(), env...) cmd.Stdin = os.Stdin cmd.Stderr = os.Stderr cmd.Stdout = os.Stdout if err := cmd.Start(); err != nil { - l.Fatal().Err(err).Str("cmd", cmd.String()).Msg("Could not start command") + l.ErrorContext(ctx, "Could not start command", "error", err, "cmd", cmd.String()) + return 1 } if err := cmd.Wait(); err != nil { @@ -146,7 +138,8 @@ func run(name string, args, env []string, l zerolog.Logger) int { if errors.As(err, &exit) { return exit.ExitCode() } - l.Fatal().Err(err).Str("cmd", cmd.String()).Msg("Unknown error while running command") + l.ErrorContext(ctx, "Unknown error while running command", "error", err, "cmd", cmd.String()) + return 1 } return 0 diff --git a/utils.go b/utils.go index bfc8cd5..a924e86 100644 --- a/utils.go +++ b/utils.go @@ -1,6 +1,10 @@ package main -import "github.com/rs/zerolog" +import ( + "context" + "fmt" + "log/slog" +) type ( Dict map[string]string @@ -11,19 +15,19 @@ type ( } ) -func loadValues(c Client, l zerolog.Logger, paths []string) Dict { +func loadValues(ctx context.Context, c Client, l *slog.Logger, paths []string) (Dict, error) { values := map[string]string{} for _, path := range paths { - l.Debug().Str("path", path).Msg("Loading values") + l.DebugContext(ctx, "Loading values", "path", path) kv, err := c.Load(path) if err != nil { - l.Fatal().Err(err).Str("path", path).Msg("Could not load values") + return values, serror(fmt.Errorf("Could not load values: %w", err), "path", path) } for k, v := range kv { values[k] = v } } - return values + return values, nil } diff --git a/utils_test.go b/utils_test.go index 49793bc..47b480f 100644 --- a/utils_test.go +++ b/utils_test.go @@ -1,13 +1,10 @@ package main import ( - "bytes" + "context" "errors" - "os" - "os/exec" "testing" - "github.com/rs/zerolog" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/mock" "github.com/stretchr/testify/require" @@ -24,42 +21,38 @@ func (m *mockClient) Load(path string) (Dict, error) { } func TestLoadValues(t *testing.T) { - log := &bytes.Buffer{} - logger := zerolog.New(log) + logger, log := testLogger() m := new(mockClient) m.On("Load", "foo").Return("foo", "bar", nil) m.On("Load", "bar").Return("bar", "baz", nil) + d, err := loadValues(context.TODO(), m, logger, []string{"foo", "bar"}) + require.NoError(t, err) assert.Equal(t, Dict{ "foo": "bar", "bar": "baz", - }, loadValues(m, logger, []string{"foo", "bar"})) + }, d) - assert.Equal(t, []byte(`{"level":"debug","path":"foo","message":"Loading values"} -{"level":"debug","path":"bar","message":"Loading values"} + assert.Equal(t, []byte(`{"time":"test-time","level":"DEBUG","msg":"Loading values","path":"foo"} +{"time":"test-time","level":"DEBUG","msg":"Loading values","path":"bar"} `), log.Bytes()) m.AssertExpectations(t) } -func TestLoadValues_Fatal(t *testing.T) { - if os.Getenv("TEST_FATAL") == "true" { - m := new(mockClient) - m.On("Load", "none").Return("", "", errors.New("test error")) //nolint:goerr113 +func TestLoadValues_Error(t *testing.T) { + logger, log := testLogger() - loadValues(m, zerolog.New(os.Stderr), []string{"none"}) - return - } + m := new(mockClient) + m.On("Load", "none").Return("", "", errors.New("test error")) //nolint:goerr113 + + d, err := loadValues(context.TODO(), m, logger, []string{"none"}) + require.ErrorContains(t, err, "Could not load values: test error") + assert.Equal(t, Dict{}, d) - cmd := exec.Command(os.Args[0], "-test.run="+t.Name()) //nolint:gosec - cmd.Env = append(cmd.Env, "TEST_FATAL=true") + assert.Equal(t, []byte(`{"time":"test-time","level":"DEBUG","msg":"Loading values","path":"none"} +`), log.Bytes()) - var exit *exec.ExitError - _, err := cmd.Output() - require.ErrorAs(t, err, &exit) - assert.Equal(t, 1, exit.ExitCode()) - assert.Equal(t, []byte(`{"level":"debug","path":"none","message":"Loading values"} -{"level":"fatal","error":"test error","path":"none","message":"Could not load values"} -`), exit.Stderr) + m.AssertExpectations(t) }