Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

use log/slog for structured logging #3502

Merged
merged 1 commit into from
Jun 1, 2024
Merged

use log/slog for structured logging #3502

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
6 changes: 3 additions & 3 deletions cmd/dex/config.go
View file
Open in desktop
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
Open in desktop
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
Open in desktop
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
Loading