Praposal for logging support for msal-go

apps/design/logging.md

@@ -0,0 +1,22 @@
+# Logging
+
+GO 1.21 introduces enhanced features like structured logging with `log/slog`.
+As part of MSAL GO, we have decided to only support logging using slog from version 1.21.
+The reason for this is `log/slog` greatly enhances the debugging and monitoring capabilities compared to the old SDK. This is especially useful in production environments where accurate, traceable logs are crucial for maintaining application health and troubleshooting issues.
+
+## **Expected Output**
+
+```plaintext
+time=2024-12-19T01:25:58.730Z level=INFO msg="This is an info message via slog." username=john_doe age=30
+time=2024-12-19T01:25:58.730Z level=ERROR msg="This is an error message via slog." module=user-service retry=3
+time=2024-12-19T01:25:58.730Z level=WARN msg="Disk space is low." free_space_mb=100
+time=2024-12-19T01:25:58.730Z level=INFO msg="Default log message." module=main
+```
+
+## Key Pointers
+
+1. **Full `slog` Support for Go 1.21+**:
+   - The `logger.go` file leverages the `slog` package, supporting structured logs, multiple log levels (`info`, `error`, `warn`), and fields.
+
+2. **Structured Logging**:
+   - You can pass key-value pairs using `slog.String`, `slog.Int`, etc., for structured logging, which is handled by `slog` in Go 1.21 and later.

apps/internal/slog/logger.go

@@ -0,0 +1,41 @@
+//go:build go1.21
+
+package slog
+
+import (
+	"context"
+	"log/slog"
+)
+
+type Level = slog.Level
+
+const (
+	LevelDebug = slog.LevelDebug
+	LevelInfo  = slog.LevelInfo
+	LevelWarn  = slog.LevelWarn
+	LevelError = slog.LevelError
+)
+
+type Handler = slog.Handler
+type Logger = slog.Logger
+type NopHandler struct{}
+
+func (*NopHandler) Enabled(context.Context, slog.Level) bool  { return false }
+func (*NopHandler) Handle(context.Context, slog.Record) error { return nil }
+func (h *NopHandler) WithAttrs([]slog.Attr) slog.Handler      { return h }
+func (h *NopHandler) WithGroup(string) slog.Handler           { return h }
+
+// New creates a new logger instance for Go 1.21+ with full `slog` logging support.
+func New(h Handler) *Logger {
+	return slog.New(h)
+}
+
+// Any creates a slog field for any value
+func Any(key string, value any) any {
+	return slog.Any(key, value)
+}
+
+// String creates a slog field for a string value
+func String(key, value string) slog.Attr {
+	return slog.String(key, value)
+}

apps/internal/slog/logger_121_below.go

@@ -0,0 +1,35 @@
+//go:build !go1.21
+
+package slog
+
+import (
+	"context"
+)
+
+type Level int
+
+type Logger struct{}
+
+const (
+	LevelDebug Level = iota
+	LevelInfo
+	LevelWarn
+	LevelError
+)
+
+type NopHandler struct{}
+
+// These are all noop functions for go < 1.21
+func New(h any) *Logger {
+	return &Logger{}
+}
+
+func Any(key string, value any) any {
+	return nil
+}
+
+func String(key, value string) any {
+	return nil
+}
+
+func (*Logger) Log(ctx context.Context, level Level, msg string, args ...any) {}

apps/internal/slog/logger_test.go

@@ -0,0 +1,64 @@
+//go:build go1.21
+
+package slog
+
+import (
+	"bytes"
+	"context"
+	"log/slog"
+	"testing"
+)
+
+func TestLogger_Log_ConsoleOutput(t *testing.T) {
+	// Capture the console output
+	var buf bytes.Buffer
+
+	// Create a new JSON handler
+	handler := slog.NewJSONHandler(&buf, &slog.HandlerOptions{
+		Level: slog.LevelDebug, // Set the log level to Debug to capture all log levels
+	})
+
+	// Create a new logger instance with the handler
+	loggerInstance := New(handler)
+
+	// Log messages
+	loggerInstance.Log(context.Background(), slog.LevelInfo, "This is an info message via slog.", slog.Any("username", "john_doe"), slog.Int("age", 30))
+	loggerInstance.Log(context.Background(), slog.LevelError, "This is an error message via slog.", slog.String("module", "user-service"), slog.Int("retry", 3))
+	loggerInstance.Log(context.Background(), slog.LevelWarn, "This is a warn message via slog.", slog.Int("free_space_mb", 100))
+	loggerInstance.Log(context.Background(), slog.LevelDebug, "This is a debug message via slog.", slog.String("module", "main"))
+
+	// Check the output
+	output := buf.String()
+	expectedMessages := []struct {
+		msg      string
+		contains []string
+	}{
+		{"This is an info message via slog.", []string{`"username":"john_doe"`, `"age":30}`}},
+		{"This is an error message via slog.", []string{`"module":"user-service"`, `"retry":3}`}},
+		{"This is a warn message via slog.", []string{`"free_space_mb":100}`}},
+		{"This is a debug message via slog.", []string{`"module":"main"`}},
+	}
+
+	for _, expected := range expectedMessages {
+		if !bytes.Contains([]byte(output), []byte(expected.msg)) {
+			t.Errorf("expected log message %q not found in output", expected.msg)
+		}
+		for _, attr := range expected.contains {
+			if !bytes.Contains([]byte(output), []byte(attr)) {
+				t.Errorf("expected attribute %q not found in output for message %q", attr, expected.msg)
+			}
+		}
+	}
+}
+
+func TestNewLogger_ValidSlogHandler(t *testing.T) {
+	// Test case where handler is a valid slog.Handler
+	var buf bytes.Buffer
+	handler := slog.NewJSONHandler(&buf, &slog.HandlerOptions{
+		Level: slog.LevelDebug,
+	})
+	logInstance := New(handler)
+	if logInstance == nil {
+		t.Fatalf("expected non-nil logInstance, got nil")
+	}
+}

apps/managedidentity/managedidentity.go

@@ -29,6 +29,7 @@ import (
 	"github.com/AzureAD/microsoft-authentication-library-for-go/apps/internal/oauth/ops/accesstokens"
 	"github.com/AzureAD/microsoft-authentication-library-for-go/apps/internal/oauth/ops/authority"
 	"github.com/AzureAD/microsoft-authentication-library-for-go/apps/internal/shared"
+	"github.com/AzureAD/microsoft-authentication-library-for-go/apps/internal/slog"
 )
 
 const (
@@ -158,11 +159,13 @@ type Client struct {
 	source             Source
 	authParams         authority.AuthParams
 	retryPolicyEnabled bool
+	logger             *slog.Logger
 }
 
 type ClientOptions struct {
 	httpClient         ops.HTTPClient
 	retryPolicyEnabled bool
+	logger             *slog.Logger
 }
 
 type AcquireTokenOptions struct {
@@ -197,8 +200,16 @@ func WithRetryPolicyDisabled() ClientOption {
 // Client to be used to acquire tokens for managed identity.
 // ID: [SystemAssigned], [UserAssignedClientID], [UserAssignedResourceID], [UserAssignedObjectID]
 //
-// Options: [WithHTTPClient]
+// Options: [WithHTTPClient], [WithLogger]
 func New(id ID, options ...ClientOption) (Client, error) {
+	opts := ClientOptions{
+		httpClient:         shared.DefaultClient,
+		retryPolicyEnabled: true,
+		logger:             slog.New(&slog.NopHandler{}),
+	}
+	for _, option := range options {
+		option(&opts)
+	}
 	source, err := GetSource()
 	if err != nil {
 		return Client{}, err
@@ -211,13 +222,6 @@ func New(id ID, options ...ClientOption) (Client, error) {
 			return Client{}, errors.New("azure Arc doesn't support user assigned managed identities")
 		}
 	}
-	opts := ClientOptions{
-		httpClient:         shared.DefaultClient,
-		retryPolicyEnabled: true,
-	}
-	for _, option := range options {
-		option(&opts)
-	}
 
 	switch t := id.(type) {
 	case UserAssignedClientID:
@@ -241,7 +245,9 @@ func New(id ID, options ...ClientOption) (Client, error) {
 		httpClient:         opts.httpClient,
 		retryPolicyEnabled: opts.retryPolicyEnabled,
 		source:             source,
+		logger:             opts.logger,
 	}
+
 	fakeAuthInfo, err := authority.NewInfoFromAuthorityURI("https://login.microsoftonline.com/managed_identity", false, true)
 	if err != nil {
 		return Client{}, err
@@ -283,8 +289,9 @@ func (c Client) AcquireToken(ctx context.Context, resource string, options ...Ac
 		option(&o)
 	}
 	c.authParams.Scopes = []string{resource}
+	c.logger.Log(ctx, slog.LevelInfo, "Managed Identity", slog.String("source", string(c.source)))
 
-	// ignore cached access tokens when given claims
+	// when claims are empty, we get token from the cache, otherwise acquire a new one
 	if o.claims == "" {
 		storageTokenResponse, err := cacheManager.Read(ctx, c.authParams)
 		if err != nil {
@@ -397,18 +404,20 @@ func (c Client) retry(maxRetries int, req *http.Request) (*http.Response, error)
 	var err error
 	for attempt := 0; attempt < maxRetries; attempt++ {
 		tryCtx, tryCancel := context.WithTimeout(req.Context(), time.Minute)
+		c.logger.Log(tryCtx, slog.LevelInfo, "Managed Identity retrying request", slog.String("attempt", fmt.Sprint(attempt)))
+
 		defer tryCancel()
 		if resp != nil && resp.Body != nil {
 			_, _ = io.Copy(io.Discard, resp.Body)
 			resp.Body.Close()
 		}
 		cloneReq := req.Clone(tryCtx)
 		resp, err = c.httpClient.Do(cloneReq)
-		retrylist := retryStatusCodes
+		retryList := retryStatusCodes
 		if c.source == DefaultToIMDS {
-			retrylist = retryCodesForIMDS
+			retryList = retryCodesForIMDS
 		}
-		if err == nil && !contains(retrylist, resp.StatusCode) {
+		if err == nil && !contains(retryList, resp.StatusCode) {
 			return resp, nil
 		}
 		select {

apps/managedidentity/managedidentity_test.go

@@ -663,6 +663,7 @@ func TestAzureArcOnlySystemAssignedSupported(t *testing.T) {
 
 	}
 }
+
 func TestAzureArcPlatformSupported(t *testing.T) {
 	setEnvVars(t, AzureArc)
 	setCustomAzureArcFilePath(t, fakeAzureArcFilePath)