Praposal for logging support for msal-go

apps/design/logging.md

@@ -0,0 +1,25 @@
+# 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.
+5rf
+3. **PII Logging (Personally Identifiable Information)**
+   - You can allow for Pii logging in the SDK by passing 'true' for piiLogging when using WithLogger() when creating the client. This defaults to false

apps/internal/slog/logger.go

@@ -0,0 +1,43 @@
+// Copyright (c) Microsoft Corporation.
+// Licensed under the MIT license.
+
+//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
+
+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,36 @@
+// Copyright (c) Microsoft Corporation.
+// Licensed under the MIT license.
+
+//go:build !go1.21
+
+package slog
+
+import (
+	"context"
+)
+
+type Level int
+
+type Logger struct{}
+
+const (
+	LevelDebug Level = iota
+	LevelInfo
+	LevelWarn
+	LevelError
+)
+
+// 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,67 @@
+// Copyright (c) Microsoft Corporation.
+// Licensed under the MIT license.
+
+//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/internal/slog/nop_handler.go

@@ -0,0 +1,6 @@
+// Copyright (c) Microsoft Corporation.
+// Licensed under the MIT license.
+
+package slog
+
+type NopHandler struct{}

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 (
@@ -160,11 +161,15 @@ type Client struct {
 	source             Source
 	authParams         authority.AuthParams
 	retryPolicyEnabled bool
+	logger             *slog.Logger
+	piiLogging         bool
 }
 
 type ClientOptions struct {
 	httpClient         ops.HTTPClient
 	retryPolicyEnabled bool
+	logger             *slog.Logger
+	piiLogging         bool
 }
 
 type AcquireTokenOptions struct {
@@ -199,7 +204,7 @@ 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) {
 	source, err := GetSource()
 	if err != nil {
@@ -233,6 +238,8 @@ func New(id ID, options ...ClientOption) (Client, error) {
 	opts := ClientOptions{
 		httpClient:         shared.DefaultClient,
 		retryPolicyEnabled: true,
+		logger:             slog.New(&slog.NopHandler{}),
+		piiLogging:         false,
 	}
 	for _, option := range options {
 		option(&opts)
@@ -260,7 +267,10 @@ func New(id ID, options ...ClientOption) (Client, error) {
 		httpClient:         opts.httpClient,
 		retryPolicyEnabled: opts.retryPolicyEnabled,
 		source:             source,
+		logger:             opts.logger,
+		piiLogging:         opts.piiLogging,
 	}
+
 	fakeAuthInfo, err := authority.NewInfoFromAuthorityURI("https://login.microsoftonline.com/managed_identity", false, true)
 	if err != nil {
 		return Client{}, err
@@ -307,8 +317,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 {
@@ -435,18 +446,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_with_funcs.go

@@ -0,0 +1,16 @@
+//go:build go1.21
+
+package managedidentity
+
+import (
+	"log/slog"
+)
+
+// WithLogger enables logging within the SDK
+// piiEnabled sets logging of Personally Identifiable Information (PII) within the SDK
+func WithLogger(l *slog.Logger, piiEnabled bool) ClientOption {
+	return func(o *ClientOptions) {
+		o.logger = l
+		o.piiLogging = piiEnabled
+	}
+}

apps/managedidentity/managedidentity_with_logger_test.go

@@ -0,0 +1,80 @@
+//go:build go1.21
+
+package managedidentity
+
+import (
+	"bytes"
+	"context"
+	"log/slog"
+	"net/http"
+	"strings"
+	"testing"
+
+	"github.com/AzureAD/microsoft-authentication-library-for-go/apps/internal/mock"
+)
+
+type BufferHandler struct {
+	buf   bytes.Buffer
+	level slog.Level
+}
+
+func (h *BufferHandler) Enabled(ctx context.Context, level slog.Level) bool {
+	return level <= h.level
+}
+
+func (h *BufferHandler) Handle(ctx context.Context, record slog.Record) error {
+	h.buf.WriteString(record.Message + " ")
+	record.Attrs(func(attr slog.Attr) bool {
+		h.buf.WriteString(attr.Key + "=" + attr.Value.String() + " ")
+		return true
+	})
+	return nil
+}
+
+func (h *BufferHandler) WithAttrs(attrs []slog.Attr) slog.Handler { return h }
+func (h *BufferHandler) WithGroup(name string) slog.Handler       { return h }
+
+func TestClientLogging(t *testing.T) {
+	mockClient := mock.Client{}
+	headers := http.Header{}
+	headers.Set("www-authenticate", "Basic realm=/path/to/secret.key")
+	mockClient.AppendResponse(mock.WithHTTPStatusCode(http.StatusUnauthorized), mock.WithHTTPHeader(headers))
+	bufferHandler := &BufferHandler{}
+	customLogger := slog.New(bufferHandler)
+
+	client, err := New(SystemAssigned(), WithHTTPClient(&mockClient), WithLogger(customLogger, false))
+	if err != nil {
+		t.Fatal(err)
+	}
+
+	_, _ = client.AcquireToken(context.Background(), "https://resource")
+
+	logOutput := bufferHandler.buf.String()
+	expectedLogMessage := "Managed Identity"
+	if !strings.Contains(logOutput, expectedLogMessage) {
+		t.Errorf("expected log message %q not found in output", expectedLogMessage)
+	}
+}
+
+func TestClientLogging_CustomHandler(t *testing.T) {
+	mockClient := mock.Client{}
+	headers := http.Header{}
+	headers.Set("www-authenticate", "Basic realm=/path/to/secret.key")
+	mockClient.AppendResponse(mock.WithHTTPStatusCode(http.StatusUnauthorized), mock.WithHTTPHeader(headers))
+
+	filteredBufferHandler := &BufferHandler{level: slog.LevelDebug}
+	customLogger := slog.New(filteredBufferHandler)
+
+	client, err := New(SystemAssigned(), WithHTTPClient(&mockClient), WithLogger(customLogger, false))
+	if err != nil {
+		t.Fatal(err)
+	}
+
+	_, _ = client.AcquireToken(context.Background(), "https://resource")
+
+	logOutput := filteredBufferHandler.buf.String()
+	unexpectedLogMessage := "Managed Identity"
+	if strings.Contains(logOutput, unexpectedLogMessage) {
+		t.Errorf("unexpected log message %q found in output", unexpectedLogMessage)
+	}
+}