Skip to content

Commit

Permalink
use slog for structured logging (#3502)
Browse files Browse the repository at this point in the history 
Signed-off-by: Sean Liao <[email protected]>
  • Loading branch information
@seankhliao
seankhliao authored Jun 1, 2024
1 parent 8e59b6d commit 0b6a783
Show file tree
Hide file tree
Showing 66 changed files with 471 additions and 604 deletions.
6 changes: 3 additions & 3 deletions cmd/dex/config.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -4,14 +4,14 @@ import (
"encoding/base64"
"encoding/json"
"fmt"
"log/slog"
"net/http"
"os"
"strings"

"golang.org/x/crypto/bcrypt"

"github.com/dexidp/dex/pkg/featureflags"
"github.com/dexidp/dex/pkg/log"
"github.com/dexidp/dex/server"
"github.com/dexidp/dex/storage"
"github.com/dexidp/dex/storage/ent"
Expand Down Expand Up @@ -236,7 +236,7 @@ type Storage struct {

// StorageConfig is a configuration that can create a storage.
type StorageConfig interface {
Open(logger log.Logger) (storage.Storage, error)
Open(logger *slog.Logger) (storage.Storage, error)
}

var (
Expand Down Expand Up @@ -386,7 +386,7 @@ type Expiry struct {
// Logger holds configuration required to customize logging for dex.
type Logger struct {
// Level sets logging level severity.
Level string `json:"level"`
Level slog.Level `json:"level"`

// Format specifies the format to be used for logging.
Format string `json:"format"`
Expand Down
5 changes: 3 additions & 2 deletions cmd/dex/config_test.go
View file
Original file line number Diff line number Diff line change
@@ -1,6 +1,7 @@
package main

import (
"log/slog"
"os"
"testing"

Expand Down Expand Up @@ -219,7 +220,7 @@ logger:
DeviceRequests: "10m",
},
Logger: Logger{
Level: "debug",
Level: slog.LevelDebug,
Format: "json",
},
}
Expand Down Expand Up @@ -426,7 +427,7 @@ logger:
AuthRequests: "25h",
},
Logger: Logger{
Level: "debug",
Level: slog.LevelDebug,
Format: "json",
},
}
Expand Down
127 changes: 52 additions & 75 deletions cmd/dex/serve.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -6,6 +6,7 @@ import (
"crypto/x509"
"errors"
"fmt"
"log/slog"
"net"
"net/http"
"net/http/pprof"
Expand All @@ -28,14 +29,12 @@ import (
"github.com/prometheus/client_golang/prometheus"
"github.com/prometheus/client_golang/prometheus/collectors"
"github.com/prometheus/client_golang/prometheus/promhttp"
"github.com/sirupsen/logrus"
"github.com/spf13/cobra"
"google.golang.org/grpc"
"google.golang.org/grpc/credentials"
"google.golang.org/grpc/reflection"

"github.com/dexidp/dex/api/v2"
"github.com/dexidp/dex/pkg/log"
"github.com/dexidp/dex/server"
"github.com/dexidp/dex/storage"
)
Expand Down Expand Up @@ -98,22 +97,24 @@ func runServe(options serveOptions) error {
return fmt.Errorf("invalid config: %v", err)
}

logger.Infof(
"Dex Version: %s, Go Version: %s, Go OS/ARCH: %s %s",
version,
runtime.Version(),
runtime.GOOS,
runtime.GOARCH,
logger.Info(
"Version info",
"dex_version", version,
slog.Group("go",
"version", runtime.Version(),
"os", runtime.GOOS,
"arch", runtime.GOARCH,
),
)

if c.Logger.Level != "" {
logger.Infof("config using log level: %s", c.Logger.Level)
if c.Logger.Level != slog.LevelInfo {
logger.Info("config using log level", "level", c.Logger.Level)
}
if err := c.Validate(); err != nil {
return err
}

logger.Infof("config issuer: %s", c.Issuer)
logger.Info("config issuer", "issuer", c.Issuer)

prometheusRegistry := prometheus.NewRegistry()
err = prometheusRegistry.Register(collectors.NewGoCollector())
Expand Down Expand Up @@ -188,7 +189,7 @@ func runServe(options serveOptions) error {
}
defer s.Close()

logger.Infof("config storage: %s", c.Storage.Type)
logger.Info("config storage", "storage_type", c.Storage.Type)

if len(c.StaticClients) > 0 {
for i, client := range c.StaticClients {
Expand All @@ -213,7 +214,7 @@ func runServe(options serveOptions) error {
}
c.StaticClients[i].Secret = os.Getenv(client.SecretEnv)
}
logger.Infof("config static client: %s", client.Name)
logger.Info("config static client", "client_name", client.Name)
}
s = storage.WithStaticClients(s, c.StaticClients)
}
Expand All @@ -233,7 +234,7 @@ func runServe(options serveOptions) error {
if c.Config == nil {
return fmt.Errorf("invalid config: no config field for connector %q", c.ID)
}
logger.Infof("config connector: %s", c.ID)
logger.Info("config connector", "connector_id", c.ID)

// convert to a storage connector object
conn, err := ToStorageConnector(c)
Expand All @@ -249,22 +250,22 @@ func runServe(options serveOptions) error {
Name: "Email",
Type: server.LocalConnector,
})
logger.Infof("config connector: local passwords enabled")
logger.Info("config connector: local passwords enabled")
}

s = storage.WithStaticConnectors(s, storageConnectors)

if len(c.OAuth2.ResponseTypes) > 0 {
logger.Infof("config response types accepted: %s", c.OAuth2.ResponseTypes)
logger.Info("config response types accepted", "response_types", c.OAuth2.ResponseTypes)
}
if c.OAuth2.SkipApprovalScreen {
logger.Infof("config skipping approval screen")
logger.Info("config skipping approval screen")
}
if c.OAuth2.PasswordConnector != "" {
logger.Infof("config using password grant connector: %s", c.OAuth2.PasswordConnector)
logger.Info("config using password grant connector", "password_connector", c.OAuth2.PasswordConnector)
}
if len(c.Web.AllowedOrigins) > 0 {
logger.Infof("config allowed origins: %s", c.Web.AllowedOrigins)
logger.Info("config allowed origins", "origins", c.Web.AllowedOrigins)
}

// explicitly convert to UTC.
Expand Down Expand Up @@ -294,31 +295,31 @@ func runServe(options serveOptions) error {
if err != nil {
return fmt.Errorf("invalid config value %q for signing keys expiry: %v", c.Expiry.SigningKeys, err)
}
logger.Infof("config signing keys expire after: %v", signingKeys)
logger.Info("config signing keys", "expire_after", signingKeys)
serverConfig.RotateKeysAfter = signingKeys
}
if c.Expiry.IDTokens != "" {
idTokens, err := time.ParseDuration(c.Expiry.IDTokens)
if err != nil {
return fmt.Errorf("invalid config value %q for id token expiry: %v", c.Expiry.IDTokens, err)
}
logger.Infof("config id tokens valid for: %v", idTokens)
logger.Info("config id tokens", "valid_for", idTokens)
serverConfig.IDTokensValidFor = idTokens
}
if c.Expiry.AuthRequests != "" {
authRequests, err := time.ParseDuration(c.Expiry.AuthRequests)
if err != nil {
return fmt.Errorf("invalid config value %q for auth request expiry: %v", c.Expiry.AuthRequests, err)
}
logger.Infof("config auth requests valid for: %v", authRequests)
logger.Info("config auth requests", "valid_for", authRequests)
serverConfig.AuthRequestsValidFor = authRequests
}
if c.Expiry.DeviceRequests != "" {
deviceRequests, err := time.ParseDuration(c.Expiry.DeviceRequests)
if err != nil {
return fmt.Errorf("invalid config value %q for device request expiry: %v", c.Expiry.AuthRequests, err)
}
logger.Infof("config device requests valid for: %v", deviceRequests)
logger.Info("config device requests", "valid_for", deviceRequests)
serverConfig.DeviceRequestsValidFor = deviceRequests
}
refreshTokenPolicy, err := server.NewRefreshTokenPolicy(
Expand Down Expand Up @@ -368,7 +369,7 @@ func runServe(options serveOptions) error {
if c.Telemetry.HTTP != "" {
const name = "telemetry"

logger.Infof("listening (%s) on %s", name, c.Telemetry.HTTP)
logger.Info("listening on", "server", name, "address", c.Telemetry.HTTP)

l, err := net.Listen("tcp", c.Telemetry.HTTP)
if err != nil {
Expand All @@ -390,9 +391,9 @@ func runServe(options serveOptions) error {
ctx, cancel := context.WithTimeout(context.Background(), time.Minute)
defer cancel()

logger.Debugf("starting graceful shutdown (%s)", name)
logger.Debug("starting graceful shutdown", "server", name)
if err := server.Shutdown(ctx); err != nil {
logger.Errorf("graceful shutdown (%s): %v", name, err)
logger.Error("graceful shutdown", "server", name, "err", err)
}
})
}
Expand All @@ -401,7 +402,7 @@ func runServe(options serveOptions) error {
if c.Web.HTTP != "" {
const name = "http"

logger.Infof("listening (%s) on %s", name, c.Web.HTTP)
logger.Info("listening on", "server", name, "address", c.Web.HTTP)

l, err := net.Listen("tcp", c.Web.HTTP)
if err != nil {
Expand All @@ -419,9 +420,9 @@ func runServe(options serveOptions) error {
ctx, cancel := context.WithTimeout(context.Background(), time.Minute)
defer cancel()

logger.Debugf("starting graceful shutdown (%s)", name)
logger.Debug("starting graceful shutdown", "server", name)
if err := server.Shutdown(ctx); err != nil {
logger.Errorf("graceful shutdown (%s): %v", name, err)
logger.Error("graceful shutdown", "server", name, "err", err)
}
})
}
Expand All @@ -430,7 +431,7 @@ func runServe(options serveOptions) error {
if c.Web.HTTPS != "" {
const name = "https"

logger.Infof("listening (%s) on %s", name, c.Web.HTTPS)
logger.Info("listening on", "server", name, "address", c.Web.HTTPS)

l, err := net.Listen("tcp", c.Web.HTTPS)
if err != nil {
Expand Down Expand Up @@ -470,16 +471,16 @@ func runServe(options serveOptions) error {
ctx, cancel := context.WithTimeout(context.Background(), time.Minute)
defer cancel()

logger.Debugf("starting graceful shutdown (%s)", name)
logger.Debug("starting graceful shutdown", "server", name)
if err := server.Shutdown(ctx); err != nil {
logger.Errorf("graceful shutdown (%s): %v", name, err)
logger.Error("graceful shutdown", "server", name, "err", err)
}
})
}

// Set up grpc server
if c.GRPC.Addr != "" {
logger.Infof("listening (grpc) on %s", c.GRPC.Addr)
logger.Info("listening on", "server", "grpc", "address", c.GRPC.Addr)

grpcListener, err := net.Listen("tcp", c.GRPC.Addr)
if err != nil {
Expand All @@ -498,7 +499,7 @@ func runServe(options serveOptions) error {
group.Add(func() error {
return grpcSrv.Serve(grpcListener)
}, func(err error) {
logger.Debugf("starting graceful shutdown (grpc)")
logger.Debug("starting graceful shutdown", "server", "grpc")
grpcSrv.GracefulStop()
})
}
Expand All @@ -508,53 +509,29 @@ func runServe(options serveOptions) error {
if _, ok := err.(run.SignalError); !ok {
return fmt.Errorf("run groups: %w", err)
}
logger.Infof("%v, shutdown now", err)
logger.Info("shutdown now", "err", err)
}
return nil
}

var (
logLevels = []string{"debug", "info", "error"}
logFormats = []string{"json", "text"}
)

type utcFormatter struct {
f logrus.Formatter
}

func (f *utcFormatter) Format(e *logrus.Entry) ([]byte, error) {
e.Time = e.Time.UTC()
return f.f.Format(e)
}
var logFormats = []string{"json", "text"}

func newLogger(level string, format string) (log.Logger, error) {
var logLevel logrus.Level
switch strings.ToLower(level) {
case "debug":
logLevel = logrus.DebugLevel
case "", "info":
logLevel = logrus.InfoLevel
case "error":
logLevel = logrus.ErrorLevel
default:
return nil, fmt.Errorf("log level is not one of the supported values (%s): %s", strings.Join(logLevels, ", "), level)
}

var formatter utcFormatter
func newLogger(level slog.Level, format string) (*slog.Logger, error) {
var handler slog.Handler
switch strings.ToLower(format) {
case "", "text":
formatter.f = &logrus.TextFormatter{DisableColors: true}
slog.NewTextHandler(os.Stderr, &slog.HandlerOptions{
Level: level,
})
case "json":
formatter.f = &logrus.JSONFormatter{}
slog.NewJSONHandler(os.Stderr, &slog.HandlerOptions{
Level: level,
})
default:
return nil, fmt.Errorf("log format is not one of the supported values (%s): %s", strings.Join(logFormats, ", "), format)
}

return &logrus.Logger{
Out: os.Stderr,
Formatter: &formatter,
Level: logLevel,
}, nil
return slog.New(handler), nil
}

func applyConfigOverrides(options serveOptions, config *Config) {
Expand Down Expand Up @@ -600,7 +577,7 @@ func pprofHandler(router *http.ServeMux) {

// newTLSReloader returns a [tls.Config] with GetCertificate or GetConfigForClient set
// to reload certificates from the given paths on SIGHUP or on file creates (atomic update via rename).
func newTLSReloader(logger log.Logger, certFile, keyFile, caFile string, baseConfig *tls.Config) (*tls.Config, error) {
func newTLSReloader(logger *slog.Logger, certFile, keyFile, caFile string, baseConfig *tls.Config) (*tls.Config, error) {
// trigger reload on channel
sigc := make(chan os.Signal, 1)
signal.Notify(sigc, syscall.SIGHUP)
Expand Down Expand Up @@ -631,7 +608,7 @@ func newTLSReloader(logger log.Logger, certFile, keyFile, caFile string, baseCon
// recommended by fsnotify: watch the dir to handle renames
// https://pkg.go.dev/github.com/fsnotify/fsnotify#hdr-Watching_files
for dir := range watchDirs {
logger.Debugf("watching dir: %v", dir)
logger.Debug("watching dir", "dir", dir)
err := watcher.Add(dir)
if err != nil {
return nil, fmt.Errorf("watch dir for TLS reloader: %v", err)
Expand All @@ -654,19 +631,19 @@ func newTLSReloader(logger log.Logger, certFile, keyFile, caFile string, baseCon
for {
select {
case sig := <-sigc:
logger.Debug("reloading cert from signal: %v", sig)
logger.Debug("reloading cert from signal", "signal", sig)
case evt := <-watcher.Events:
if _, ok := watchFiles[evt.Name]; !ok || !evt.Has(fsnotify.Create) {
continue loop
}
logger.Debug("reloading cert from fsnotify: %v %v", evt.Name, evt.Op.String())
logger.Debug("reloading cert from fsnotify", "event", evt.Name, "operation", evt.Op.String())
case err := <-watcher.Errors:
logger.Errorf("TLS reloader watch: %v", err)
logger.Error("TLS reloader watch", "err", err)
}

loaded, err := loadTLSConfig(certFile, keyFile, caFile, baseConfig)
if err != nil {
logger.Errorf("reload TLS config: %v", err)
logger.Error("reload TLS config", "err", err)
}
ptr.Store(loaded)
}
Expand Down
Loading

0 comments on commit 0b6a783

Please sign in to comment.