Improve logging

+ Add more debug logs for tokens' introspection.
+ Provide an ability to use custom request-scoped logger.
+ Fix duplicated log prefix issue.

auth.go

@@ -7,41 +7,42 @@ Released under MIT license.
 package authkit
 
 import (
+	"context"
 	"crypto/tls"
 	"crypto/x509"
 	"fmt"
 	"net/http"
 	"os"
 
+	"github.com/acronis/go-appkit/httpserver/middleware"
 	"github.com/acronis/go-appkit/log"
 	"google.golang.org/grpc/credentials"
 	"google.golang.org/grpc/credentials/insecure"
 
 	"github.com/acronis/go-authkit/idptoken"
 	"github.com/acronis/go-authkit/internal/idputil"
+	"github.com/acronis/go-authkit/internal/libinfo"
 	"github.com/acronis/go-authkit/jwks"
 	"github.com/acronis/go-authkit/jwt"
 )
 
 // NewJWTParser creates a new JWTParser with the given configuration.
 // If cfg.JWT.ClaimsCache.Enabled is true, then jwt.CachingParser created, otherwise - jwt.Parser.
 func NewJWTParser(cfg *Config, opts ...JWTParserOption) (JWTParser, error) {
-	var options jwtParserOptions
+	options := jwtParserOptions{loggerProvider: middleware.GetLoggerFromContext}
 	for _, opt := range opts {
 		opt(&options)
 	}
 
-	logger := idputil.PrepareLogger(options.logger)
-
 	// Make caching JWKS client.
 	jwksCacheUpdateMinInterval := cfg.JWKS.Cache.UpdateMinInterval
 	if jwksCacheUpdateMinInterval == 0 {
 		jwksCacheUpdateMinInterval = jwks.DefaultCacheUpdateMinInterval
 	}
 	jwksClientOpts := jwks.CachingClientOpts{
 		ClientOpts: jwks.ClientOpts{
-			Logger:                     logger,
-			HTTPClient:                 idputil.MakeDefaultHTTPClient(cfg.HTTPClient.RequestTimeout, logger),
+			LoggerProvider:             options.loggerProvider,
+			HTTPClient:                 idputil.MakeDefaultHTTPClient(cfg.HTTPClient.RequestTimeout, options.loggerProvider),
 			PrometheusLibInstanceLabel: options.prometheusLibInstanceLabel,
 		},
 		CacheUpdateMinInterval: jwksCacheUpdateMinInterval,
@@ -51,17 +52,19 @@ func NewJWTParser(cfg *Config, opts ...JWTParserOption) (JWTParser, error) {
 	// Make JWT parser.
 
 	if len(cfg.JWT.TrustedIssuers) == 0 && len(cfg.JWT.TrustedIssuerURLs) == 0 {
-		logger.Warn("list of trusted issuers is empty, jwt parsing may not work properly")
+		idputil.GetLoggerFromProvider(context.Background(), options.loggerProvider).Warn(
+			"list of trusted issuers is empty, jwt parsing may not work properly")
 	}
 
 	parserOpts := jwt.ParserOpts{
 		RequireAudience:               cfg.JWT.RequireAudience,
 		ExpectedAudience:              cfg.JWT.ExpectedAudience,
 		TrustedIssuerNotFoundFallback: options.trustedIssuerNotFoundFallback,
+		LoggerProvider:                options.loggerProvider,
 	}
 
 	if cfg.JWT.ClaimsCache.Enabled {
-		cachingJWTParser, err := jwt.NewCachingParserWithOpts(jwksClient, logger, jwt.CachingParserOpts{
+		cachingJWTParser, err := jwt.NewCachingParserWithOpts(jwksClient, jwt.CachingParserOpts{
 			ParserOpts:      parserOpts,
 			CacheMaxEntries: cfg.JWT.ClaimsCache.MaxEntries,
 		})
@@ -74,26 +77,26 @@ func NewJWTParser(cfg *Config, opts ...JWTParserOption) (JWTParser, error) {
 		return cachingJWTParser, nil
 	}
 
-	jwtParser := jwt.NewParserWithOpts(jwksClient, logger, parserOpts)
+	jwtParser := jwt.NewParserWithOpts(jwksClient, parserOpts)
 	if err := addTrustedIssuers(jwtParser, cfg.JWT.TrustedIssuers, cfg.JWT.TrustedIssuerURLs); err != nil {
 		return nil, err
 	}
 	return jwtParser, nil
 }
 
 type jwtParserOptions struct {
-	logger                        log.FieldLogger
+	loggerProvider                func(ctx context.Context) log.FieldLogger
 	prometheusLibInstanceLabel    string
 	trustedIssuerNotFoundFallback jwt.TrustedIssNotFoundFallback
 }
 
 // JWTParserOption is an option for creating JWTParser.
 type JWTParserOption func(options *jwtParserOptions)
 
-// WithJWTParserLogger sets the logger for JWTParser.
-func WithJWTParserLogger(logger log.FieldLogger) JWTParserOption {
+// WithJWTParserLoggerProvider sets the logger provider for JWTParser.
+func WithJWTParserLoggerProvider(loggerProvider func(ctx context.Context) log.FieldLogger) JWTParserOption {
 	return func(options *jwtParserOptions) {
-		options.logger = logger
+		options.loggerProvider = loggerProvider
 	}
 }
 
@@ -122,15 +125,14 @@ func NewTokenIntrospector(
 	scopeFilter []idptoken.IntrospectionScopeFilterAccessPolicy,
 	opts ...TokenIntrospectorOption,
 ) (*idptoken.Introspector, error) {
-	var options tokenIntrospectorOptions
+	options := tokenIntrospectorOptions{loggerProvider: middleware.GetLoggerFromContext}
 	for _, opt := range opts {
 		opt(&options)
 	}
 
-	logger := idputil.PrepareLogger(options.logger)
-
 	if len(cfg.JWT.TrustedIssuers) == 0 && len(cfg.JWT.TrustedIssuerURLs) == 0 {
-		logger.Warn("list of trusted issuers is empty, jwt introspection may not work properly")
+		idputil.GetLoggerFromProvider(context.Background(), options.loggerProvider).Warn(
+			"list of trusted issuers is empty, jwt introspection may not work properly")
 	}
 
 	var grpcClient *idptoken.GRPCClient
@@ -139,19 +141,24 @@ func NewTokenIntrospector(
 		if err != nil {
 			return nil, fmt.Errorf("make grpc transport credentials: %w", err)
 		}
-		grpcClient, err = idptoken.NewGRPCClientWithOpts(cfg.Introspection.GRPC.Endpoint, transportCreds,
-			idptoken.GRPCClientOpts{RequestTimeout: cfg.GRPCClient.RequestTimeout, Logger: logger})
-		if err != nil {
+		grpcClientOpts := idptoken.GRPCClientOpts{
+			RequestTimeout: cfg.GRPCClient.RequestTimeout,
+			LoggerProvider: options.loggerProvider,
+			UserAgent:      libinfo.UserAgent(),
+		}
+		if grpcClient, err = idptoken.NewGRPCClientWithOpts(
+			cfg.Introspection.GRPC.Endpoint, transportCreds, grpcClientOpts,
+		); err != nil {
 			return nil, fmt.Errorf("new grpc client: %w", err)
 		}
 	}
 
 	introspectorOpts := idptoken.IntrospectorOpts{
 		HTTPEndpoint:                  cfg.Introspection.Endpoint,
 		GRPCClient:                    grpcClient,
-		HTTPClient:                    idputil.MakeDefaultHTTPClient(cfg.HTTPClient.RequestTimeout, logger),
+		HTTPClient:                    idputil.MakeDefaultHTTPClient(cfg.HTTPClient.RequestTimeout, options.loggerProvider),
 		AccessTokenScope:              cfg.Introspection.AccessTokenScope,
-		Logger:                        logger,
+		LoggerProvider:                options.loggerProvider,
 		ScopeFilter:                   scopeFilter,
 		TrustedIssuerNotFoundFallback: options.trustedIssuerNotFoundFallback,
 		PrometheusLibInstanceLabel:    options.prometheusLibInstanceLabel,
@@ -179,18 +186,18 @@ func NewTokenIntrospector(
 }
 
 type tokenIntrospectorOptions struct {
-	logger                        log.FieldLogger
+	loggerProvider                func(ctx context.Context) log.FieldLogger
 	prometheusLibInstanceLabel    string
 	trustedIssuerNotFoundFallback idptoken.TrustedIssNotFoundFallback
 }
 
 // TokenIntrospectorOption is an option for creating TokenIntrospector.
 type TokenIntrospectorOption func(options *tokenIntrospectorOptions)
 
-// WithTokenIntrospectorLogger sets the logger for TokenIntrospector.
-func WithTokenIntrospectorLogger(logger log.FieldLogger) TokenIntrospectorOption {
+// WithTokenIntrospectorLoggerProvider sets the logger provider for TokenIntrospector.
+func WithTokenIntrospectorLoggerProvider(loggerProvider func(ctx context.Context) log.FieldLogger) TokenIntrospectorOption {
 	return func(options *tokenIntrospectorOptions) {
-		options.logger = logger
+		options.loggerProvider = loggerProvider
 	}
 }
 
@@ -242,6 +249,11 @@ func NewVerifyAccessByRolesInJWTMaker(namespace string) func(roleNames ...string
 	}
 }
 
+// SetDefaultLogger sets the default logger for the library.
+func SetDefaultLogger(logger log.FieldLogger) {
+	idputil.DefaultLogger = logger
+}
+
 type issuerParser interface {
 	AddTrustedIssuer(issName string, issURL string)
 	AddTrustedIssuerURL(issURL string) error

examples/authn-middleware/main.go

@@ -39,20 +39,19 @@ func runApp() error {
 	logger, loggerClose := log.NewLogger(cfg.Log)
 	defer loggerClose()
 
-	jwtParser, err := authkit.NewJWTParser(cfg.Auth, authkit.WithJWTParserLogger(logger))
+	jwtParser, err := authkit.NewJWTParser(cfg.Auth)
 	if err != nil {
 		return fmt.Errorf("create JWT parser: %w", err)
 	}
 
-	logMw := middleware.Logging(logger)
 	authNMw := authkit.JWTAuthMiddleware(serviceErrorDomain, jwtParser)
 
 	srvMux := http.NewServeMux()
-	srvMux.Handle("/", logMw(authNMw(http.HandlerFunc(func(rw http.ResponseWriter, r *http.Request) {
+	srvMux.Handle("/", authNMw(http.HandlerFunc(func(rw http.ResponseWriter, r *http.Request) {
 		jwtClaims := authkit.GetJWTClaimsFromContext(r.Context()) // get JWT claims from the request context
 		_, _ = rw.Write([]byte(fmt.Sprintf("Hello, %s", jwtClaims.Subject)))
-	}))))
-	if err = http.ListenAndServe(":8080", srvMux); err != nil && !errors.Is(err, http.ErrServerClosed) {
+	})))
+	if err = http.ListenAndServe(":8080", middleware.Logging(logger)(srvMux)); err != nil && !errors.Is(err, http.ErrServerClosed) {
 		return fmt.Errorf("listen and HTTP server: %w", err)
 	}
 

examples/idp-test-server/main.go

@@ -9,6 +9,7 @@ package main
 import (
 	"context"
 	"errors"
+	"fmt"
 	golog "log"
 	"net/http"
 	"os"
@@ -22,7 +23,6 @@ import (
 	"github.com/acronis/go-authkit"
 	"github.com/acronis/go-authkit/idptest"
 	"github.com/acronis/go-authkit/idptoken"
-	"github.com/acronis/go-authkit/jwks"
 	"github.com/acronis/go-authkit/jwt"
 )
 
@@ -38,18 +38,20 @@ func runApp() error {
 	logger, loggerClose := log.NewLogger(&log.Config{Output: log.OutputStdout, Level: log.LevelInfo, Format: log.FormatJSON})
 	defer loggerClose()
 
-	jwksClientOpts := jwks.CachingClientOpts{ClientOpts: jwks.ClientOpts{Logger: logger}}
-	jwtParser := jwt.NewParser(jwks.NewCachingClientWithOpts(jwksClientOpts), logger)
-	_ = jwtParser.AddTrustedIssuerURL("http://" + idpAddr)
+	jwtParser, err := authkit.NewJWTParser(
+		&authkit.Config{JWT: authkit.JWTConfig{TrustedIssuerURLs: []string{"http://" + idpAddr}}})
+	if err != nil {
+		return fmt.Errorf("create JWT parser: %w", err)
+	}
 
 	idpSrv := idptest.NewHTTPServer(
 		idptest.WithHTTPAddress(idpAddr),
 		idptest.WithHTTPMiddleware(middleware.Logging(logger)),
 		idptest.WithHTTPClaimsProvider(&demoClaimsProvider{}),
 		idptest.WithHTTPTokenIntrospector(&demoTokenIntrospector{jwtParser: jwtParser}),
 	)
-	if err := idpSrv.StartAndWaitForReady(time.Second * 3); err != nil {
-		return err
+	if err = idpSrv.StartAndWaitForReady(time.Second * 3); err != nil {
+		return fmt.Errorf("start HTTP server: %w", err)
 	}
 	logger.Info("HTTP IDP server is running on " + idpAddr)
 
@@ -61,13 +63,13 @@ func runApp() error {
 	defer shutdownCancel()
 
 	if stopErr := idpSrv.Shutdown(shutdownCtx); stopErr != nil && !errors.Is(stopErr, http.ErrServerClosed) {
-		return stopErr
+		return fmt.Errorf("shutdown HTTP server: %w", stopErr)
 	}
 	return nil
 }
 
 type demoTokenIntrospector struct {
-	jwtParser *jwt.Parser
+	jwtParser authkit.JWTParser
 }
 
 func (dti *demoTokenIntrospector) IntrospectToken(r *http.Request, token string) (idptoken.IntrospectionResult, error) {

examples/token-introspection/config.yml

@@ -20,4 +20,4 @@ auth:
       maxEntries: 1000
       ttl: 5m
     grpc:
-      endpoint: 127.0.0.1:50051
+      endpoint: ""

examples/token-introspection/grpc-server/main.go

@@ -8,6 +8,7 @@ package main
 
 import (
 	"context"
+	"fmt"
 	golog "log"
 	"os"
 	"os/signal"
@@ -17,9 +18,9 @@ import (
 	"github.com/acronis/go-appkit/log"
 	"google.golang.org/grpc/metadata"
 
+	"github.com/acronis/go-authkit"
 	"github.com/acronis/go-authkit/idptest"
 	"github.com/acronis/go-authkit/idptoken/pb"
-	"github.com/acronis/go-authkit/jwks"
 	"github.com/acronis/go-authkit/jwt"
 )
 
@@ -38,15 +39,17 @@ func runApp() error {
 	logger, loggerClose := log.NewLogger(&log.Config{Output: log.OutputStdout, Level: log.LevelInfo, Format: log.FormatJSON})
 	defer loggerClose()
 
-	jwksClientOpts := jwks.CachingClientOpts{ClientOpts: jwks.ClientOpts{Logger: logger}}
-	jwtParser := jwt.NewParser(jwks.NewCachingClientWithOpts(jwksClientOpts), logger)
-	_ = jwtParser.AddTrustedIssuerURL("http://" + idpAddr)
+	jwtParser, err := authkit.NewJWTParser(
+		&authkit.Config{JWT: authkit.JWTConfig{TrustedIssuerURLs: []string{"http://" + idpAddr}}})
+	if err != nil {
+		return fmt.Errorf("create JWT parser: %w", err)
+	}
 
 	grpcSrv := idptest.NewGRPCServer(
 		idptest.WithGRPCAddr(grpcAddr),
 		idptest.WithGRPCTokenIntrospector(&demoGRPCTokenIntrospector{jwtParser: jwtParser, logger: logger}),
 	)
-	if err := grpcSrv.StartAndWaitForReady(time.Second * 3); err != nil {
+	if err = grpcSrv.StartAndWaitForReady(time.Second * 3); err != nil {
 		return err
 	}
 	logger.Info("GRPC server for token introspection is running on " + grpcAddr)
@@ -62,18 +65,26 @@ func runApp() error {
 const accessTokenWithIntrospectionPermission = "access-token-with-introspection-permission"
 
 type demoGRPCTokenIntrospector struct {
-	jwtParser *jwt.Parser
+	jwtParser authkit.JWTParser
 	logger    log.FieldLogger
 }
 
 func (dti *demoGRPCTokenIntrospector) IntrospectToken(
 	ctx context.Context, req *pb.IntrospectTokenRequest,
 ) (*pb.IntrospectTokenResponse, error) {
-	dti.logger.Info("got IntrospectTokenRequest")
+	var userAgent string
 	var authMeta string
-	if mdVal := metadata.ValueFromIncomingContext(ctx, "authorization"); len(mdVal) != 0 {
-		authMeta = mdVal[0]
+	if md, ok := metadata.FromIncomingContext(ctx); ok {
+		if userAgentList := md.Get("user-agent"); len(userAgentList) > 0 {
+			userAgent = userAgentList[0]
+		}
+		if authList := md.Get("authorization"); len(authList) > 0 {
+			authMeta = authList[0]
+		}
 	}
+
+	dti.logger.Info("got IntrospectTokenRequest", log.String("user_agent", userAgent))
+
 	if authMeta != "Bearer "+accessTokenWithIntrospectionPermission {
 		return nil, idptest.ErrUnauthorized
 	}

examples/token-introspection/main.go

@@ -43,16 +43,14 @@ func runApp() error {
 	defer loggerClose()
 
 	// Create JWT parser.
-	jwtParser, err := authkit.NewJWTParser(cfg.Auth, authkit.WithJWTParserLogger(logger))
+	jwtParser, err := authkit.NewJWTParser(cfg.Auth)
 	if err != nil {
 		return fmt.Errorf("create JWT parser: %w", err)
 	}
 
 	// Create token introspector.
-	introspectionScopeFilter := []idptoken.IntrospectionScopeFilterAccessPolicy{
-		{ResourceNamespace: serviceAccessPolicy}}
-	tokenIntrospector, err := authkit.NewTokenIntrospector(cfg.Auth, introspectionTokenProvider{},
-		introspectionScopeFilter, authkit.WithTokenIntrospectorLogger(logger))
+	introspectionScopeFilter := []idptoken.IntrospectionScopeFilterAccessPolicy{{ResourceNamespace: serviceAccessPolicy}}
+	tokenIntrospector, err := authkit.NewTokenIntrospector(cfg.Auth, introspectionTokenProvider{}, introspectionScopeFilter)
 	if err != nil {
 		return fmt.Errorf("create token introspector: %w", err)
 	}
@@ -65,8 +63,6 @@ func runApp() error {
 		}()
 	}
 
-	logMw := middleware.Logging(logger)
-
 	// Configure JWTAuthMiddleware that performs only authentication via OAuth2 token introspection endpoint.
 	authNMw := authkit.JWTAuthMiddleware(serviceErrorDomain, jwtParser,
 		authkit.WithJWTAuthMiddlewareTokenIntrospector(tokenIntrospector))
@@ -81,16 +77,16 @@ func runApp() error {
 	// Create HTTP server and start it.
 	srvMux := http.NewServeMux()
 	// "/" endpoint will be available for all authenticated users.
-	srvMux.Handle("/", logMw(authNMw(http.HandlerFunc(func(rw http.ResponseWriter, r *http.Request) {
+	srvMux.Handle("/", authNMw(http.HandlerFunc(func(rw http.ResponseWriter, r *http.Request) {
 		jwtClaims := authkit.GetJWTClaimsFromContext(r.Context()) // get JWT claims from the request context
 		_, _ = rw.Write([]byte(fmt.Sprintf("Hello, %s", jwtClaims.Subject)))
-	}))))
+	})))
 	// "/admin" endpoint will be available only for users with the "admin" role.
-	srvMux.Handle("/admin", logMw(authZMw(http.HandlerFunc(func(rw http.ResponseWriter, r *http.Request) {
+	srvMux.Handle("/admin", authZMw(http.HandlerFunc(func(rw http.ResponseWriter, r *http.Request) {
 		jwtClaims := authkit.GetJWTClaimsFromContext(r.Context()) // Get JWT claims from the request context.
 		_, _ = rw.Write([]byte(fmt.Sprintf("Hi, %s", jwtClaims.Subject)))
-	}))))
-	if err = http.ListenAndServe(":8080", srvMux); err != nil && !errors.Is(err, http.ErrServerClosed) {
+	})))
+	if err = http.ListenAndServe(":8080", middleware.Logging(logger)(srvMux)); err != nil && !errors.Is(err, http.ErrServerClosed) {
 		return fmt.Errorf("listen and HTTP server: %w", err)
 	}