diff --git a/apps/design/logging.md b/apps/design/logging.md new file mode 100644 index 00000000..187be23e --- /dev/null +++ b/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 diff --git a/apps/internal/slog/logger.go b/apps/internal/slog/logger.go new file mode 100644 index 00000000..2a1ff6a3 --- /dev/null +++ b/apps/internal/slog/logger.go @@ -0,0 +1,44 @@ +// 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 +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) +} diff --git a/apps/internal/slog/logger_121_below.go b/apps/internal/slog/logger_121_below.go new file mode 100644 index 00000000..65d74156 --- /dev/null +++ b/apps/internal/slog/logger_121_below.go @@ -0,0 +1,37 @@ +// Copyright (c) Microsoft Corporation. +// Licensed under the MIT license. + +//go:build !go1.21 + +package slog + +import ( + "context" +) + +type NopHandler struct{} +type Logger struct{} + +type Level int + +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) {} diff --git a/apps/internal/slog/logger_test.go b/apps/internal/slog/logger_test.go new file mode 100644 index 00000000..80ff5f33 --- /dev/null +++ b/apps/internal/slog/logger_test.go @@ -0,0 +1,55 @@ +// 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) + } + } + } +} diff --git a/apps/managedidentity/managedidentity.go b/apps/managedidentity/managedidentity.go index 61bb39c0..583e6f92 100644 --- a/apps/managedidentity/managedidentity.go +++ b/apps/managedidentity/managedidentity.go @@ -20,6 +20,7 @@ import ( "path/filepath" "runtime" "strings" + "sync" "time" "github.com/AzureAD/microsoft-authentication-library-for-go/apps/errors" @@ -29,6 +30,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 ( @@ -131,6 +133,7 @@ var getAzureArcHimdsFilePath = func(platform string) string { return "" } } +var logOnce sync.Once type Source string @@ -160,11 +163,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 +206,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 +240,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 +269,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 @@ -301,6 +313,10 @@ func GetSource() (Source, error) { // Resource: scopes application is requesting access to // Options: [WithClaims] func (c Client) AcquireToken(ctx context.Context, resource string, options ...AcquireTokenOption) (base.AuthResult, error) { + logOnce.Do(func() { + c.logger.Log(ctx, slog.LevelInfo, "Managed Identity", slog.String("source", string(c.source))) + }) + resource = strings.TrimSuffix(resource, "/.default") o := AcquireTokenOptions{} for _, option := range options { @@ -308,7 +324,7 @@ func (c Client) AcquireToken(ctx context.Context, resource string, options ...Ac } c.authParams.Scopes = []string{resource} - // 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,6 +451,8 @@ 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) @@ -442,11 +460,11 @@ func (c Client) retry(maxRetries int, req *http.Request) (*http.Response, error) } 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 { diff --git a/apps/managedidentity/managedidentity_with_logger_test.go b/apps/managedidentity/managedidentity_with_logger_test.go new file mode 100644 index 00000000..6bf03fac --- /dev/null +++ b/apps/managedidentity/managedidentity_with_logger_test.go @@ -0,0 +1,74 @@ +// Copyright (c) Microsoft Corporation. +// Licensed under the MIT license. + +//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{} + mockClient.AppendResponse(mock.WithHTTPStatusCode(http.StatusUnauthorized)) + 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) + } + + mockClient.AppendResponse(mock.WithHTTPStatusCode(http.StatusUnauthorized)) + 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() + + if strings.Contains(logOutput, expectedLogMessage) { + t.Errorf("unexpected log message %q found in output", expectedLogMessage) + } +} diff --git a/apps/managedidentity/options.go b/apps/managedidentity/options.go new file mode 100644 index 00000000..637f528c --- /dev/null +++ b/apps/managedidentity/options.go @@ -0,0 +1,19 @@ +// Copyright (c) Microsoft Corporation. +// Licensed under the MIT license. + +//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 + } +}