feat: add slog logging (#432)

* feat(op): user slog for logging

integrate with golang.org/x/exp/slog for logging.
provide a middleware for request scoped logging.

BREAKING CHANGES:

1. OpenIDProvider and sub-interfaces get a Logger()
method to return the configured logger;
2. AuthRequestError now takes the complete Authorizer,
instead of only the encoder. So that it may use its Logger() method.
3. RequestError now takes a Logger as argument.

* use zitadel/logging

* finish op and testing
without middleware for now

* minimum go version 1.19

* update go mod

* log value testing only on go 1.20 or later

* finish the RP and example

* ping logging release

example/client/app/app.go

@@ -7,11 +7,14 @@ import (
 	"net/http"
 	"os"
 	"strings"
+	"sync/atomic"
 	"time"
 
 	"github.com/google/uuid"
 	"github.com/sirupsen/logrus"
+	"golang.org/x/exp/slog"
 
+	"github.com/zitadel/logging"
 	"github.com/zitadel/oidc/v3/pkg/client/rp"
 	httphelper "github.com/zitadel/oidc/v3/pkg/http"
 	"github.com/zitadel/oidc/v3/pkg/oidc"
@@ -33,9 +36,25 @@ func main() {
 	redirectURI := fmt.Sprintf("http://localhost:%v%v", port, callbackPath)
 	cookieHandler := httphelper.NewCookieHandler(key, key, httphelper.WithUnsecure())
 
+	logger := slog.New(
+		slog.NewTextHandler(os.Stderr, &slog.HandlerOptions{
+			AddSource: true,
+			Level:     slog.LevelDebug,
+		}),
+	)
+	client := &http.Client{
+		Timeout: time.Minute,
+	}
+	// enable outgoing request logging
+	logging.EnableHTTPClient(client,
+		logging.WithClientGroup("client"),
+	)
+
 	options := []rp.Option{
 		rp.WithCookieHandler(cookieHandler),
 		rp.WithVerifierOpts(rp.WithIssuedAtOffset(5 * time.Second)),
+		rp.WithHTTPClient(client),
+		rp.WithLogger(logger),
 	}
 	if clientSecret == "" {
 		options = append(options, rp.WithPKCE(cookieHandler))
@@ -44,7 +63,10 @@ func main() {
 		options = append(options, rp.WithJWTProfile(rp.SignerFromKeyPath(keyPath)))
 	}
 
-	provider, err := rp.NewRelyingPartyOIDC(context.TODO(), issuer, clientID, clientSecret, redirectURI, scopes, options...)
+	// One can add a logger to the context,
+	// pre-defining log attributes as required.
+	ctx := logging.ToContext(context.TODO(), logger)
+	provider, err := rp.NewRelyingPartyOIDC(ctx, issuer, clientID, clientSecret, redirectURI, scopes, options...)
 	if err != nil {
 		logrus.Fatalf("error creating provider %s", err.Error())
 	}
@@ -119,8 +141,22 @@ func main() {
 	//
 	// http.Handle(callbackPath, rp.CodeExchangeHandler(marshalToken, provider))
 
+	// simple counter for request IDs
+	var counter atomic.Int64
+	// enable incomming request logging
+	mw := logging.Middleware(
+		logging.WithLogger(logger),
+		logging.WithGroup("server"),
+		logging.WithIDFunc(func() slog.Attr {
+			return slog.Int64("id", counter.Add(1))
+		}),
+	)
+
 	lis := fmt.Sprintf("127.0.0.1:%s", port)
-	logrus.Infof("listening on http://%s/", lis)
-	logrus.Info("press ctrl+c to stop")
-	logrus.Fatal(http.ListenAndServe(lis, nil))
+	logger.Info("server listening, press ctrl+c to stop", "addr", lis)
+	err = http.ListenAndServe(lis, mw(http.DefaultServeMux))
+	if err != http.ErrServerClosed {
+		logger.Error("server terminated", "error", err)
+		os.Exit(1)
+	}
 }

example/server/exampleop/op.go

@@ -4,9 +4,12 @@ import (
 	"crypto/sha256"
 	"log"
 	"net/http"
+	"sync/atomic"
 	"time"
 
 	"github.com/go-chi/chi"
+	"github.com/zitadel/logging"
+	"golang.org/x/exp/slog"
 	"golang.org/x/text/language"
 
 	"github.com/zitadel/oidc/v3/example/server/storage"
@@ -31,26 +34,33 @@ type Storage interface {
 	deviceAuthenticate
 }
 
+// simple counter for request IDs
+var counter atomic.Int64
+
 // SetupServer creates an OIDC server with Issuer=http://localhost:<port>
 //
 // Use one of the pre-made clients in storage/clients.go or register a new one.
-func SetupServer(issuer string, storage Storage) chi.Router {
+func SetupServer(issuer string, storage Storage, logger *slog.Logger) chi.Router {
 	// the OpenID Provider requires a 32-byte key for (token) encryption
 	// be sure to create a proper crypto random key and manage it securely!
 	key := sha256.Sum256([]byte("test"))
 
 	router := chi.NewRouter()
+	router.Use(logging.Middleware(
+		logging.WithLogger(logger),
+		logging.WithIDFunc(func() slog.Attr {
+			return slog.Int64("id", counter.Add(1))
+		}),
+	))
 
 	// for simplicity, we provide a very small default page for users who have signed out
 	router.HandleFunc(pathLoggedOut, func(w http.ResponseWriter, req *http.Request) {
-		_, err := w.Write([]byte("signed out successfully"))
-		if err != nil {
-			log.Printf("error serving logged out page: %v", err)
-		}
+		w.Write([]byte("signed out successfully"))
+		// no need to check/log error, this will be handeled by the middleware.
 	})
 
 	// creation of the OpenIDProvider with the just created in-memory Storage
-	provider, err := newOP(storage, issuer, key)
+	provider, err := newOP(storage, issuer, key, logger)
 	if err != nil {
 		log.Fatal(err)
 	}
@@ -80,7 +90,7 @@ func SetupServer(issuer string, storage Storage) chi.Router {
 // newOP will create an OpenID Provider for localhost on a specified port with a given encryption key
 // and a predefined default logout uri
 // it will enable all options (see descriptions)
-func newOP(storage op.Storage, issuer string, key [32]byte) (op.OpenIDProvider, error) {
+func newOP(storage op.Storage, issuer string, key [32]byte, logger *slog.Logger) (op.OpenIDProvider, error) {
 	config := &op.Config{
 		CryptoKey: key,
 
@@ -117,6 +127,8 @@ func newOP(storage op.Storage, issuer string, key [32]byte) (op.OpenIDProvider,
 		op.WithAllowInsecure(),
 		// as an example on how to customize an endpoint this will change the authorization_endpoint from /authorize to /auth
 		op.WithCustomAuthEndpoint(op.NewEndpoint("auth")),
+		// Pass our logger to the OP
+		op.WithLogger(logger.WithGroup("op")),
 	)
 	if err != nil {
 		return nil, err

example/server/main.go

@@ -2,11 +2,12 @@ package main
 
 import (
 	"fmt"
-	"log"
 	"net/http"
+	"os"
 
 	"github.com/zitadel/oidc/v3/example/server/exampleop"
 	"github.com/zitadel/oidc/v3/example/server/storage"
+	"golang.org/x/exp/slog"
 )
 
 func main() {
@@ -20,16 +21,22 @@ func main() {
 	// in this example it will be handled in-memory
 	storage := storage.NewStorage(storage.NewUserStore(issuer))
 
-	router := exampleop.SetupServer(issuer, storage)
+	logger := slog.New(
+		slog.NewTextHandler(os.Stderr, &slog.HandlerOptions{
+			AddSource: true,
+			Level:     slog.LevelDebug,
+		}),
+	)
+	router := exampleop.SetupServer(issuer, storage, logger)
 
 	server := &http.Server{
 		Addr:    ":" + port,
 		Handler: router,
 	}
-	log.Printf("server listening on http://localhost:%s/", port)
-	log.Println("press ctrl+c to stop")
+	logger.Info("server listening, press ctrl+c to stop", "addr", fmt.Sprintf("http://localhost:%s/", port))
 	err := server.ListenAndServe()
-	if err != nil {
-		log.Fatal(err)
+	if err != http.ErrServerClosed {
+		logger.Error("server terminated", "error", err)
+		os.Exit(1)
 	}
 }

example/server/storage/oidc.go

@@ -3,6 +3,7 @@ package storage
 import (
 	"time"
 
+	"golang.org/x/exp/slog"
 	"golang.org/x/text/language"
 
 	"github.com/zitadel/oidc/v3/pkg/oidc"
@@ -41,6 +42,19 @@ type AuthRequest struct {
 	authTime time.Time
 }
 
+// LogValue allows you to define which fields will be logged.
+// Implements the [slog.LogValuer]
+func (a *AuthRequest) LogValue() slog.Value {
+	return slog.GroupValue(
+		slog.String("id", a.ID),
+		slog.Time("creation_date", a.CreationDate),
+		slog.Any("scopes", a.Scopes),
+		slog.String("response_type", string(a.ResponseType)),
+		slog.String("app_id", a.ApplicationID),
+		slog.String("callback_uri", a.CallbackURI),
+	)
+}
+
 func (a *AuthRequest) GetID() string {
 	return a.ID
 }