Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

feat: add logging hook, rm logging from evaluation #289

Merged
merged 13 commits into from
Oct 23, 2024
Merged
Show file tree
Hide file tree
Changes from 10 commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
17 changes: 5 additions & 12 deletions README.md
Original file line number Diff line number Diff line change
Expand Up @@ -175,21 +175,14 @@ value, err := client.BooleanValue(

### Logging

The standard Go log package is used by default to show error logs.
This can be overridden using the structured logging, [logr](https://github.com/go-logr/logr) API, allowing integration to any package.
There are already [integration implementations](https://github.com/go-logr/logr#implementations-non-exhaustive) for many of the popular logger packages.
Note that in accordance with the OpenFeature specification, the SDK doesn't generally log messages during flag evaluation.

```go
var l logr.Logger
l = integratedlogr.New() // replace with your chosen integrator

openfeature.SetLogger(l) // set the logger at global level
#### Logging Hook

c := openfeature.NewClient("log").WithLogger(l) // set the logger at client level
```
The GO SDK includes a `LoggingHook`, which logs detailed information at key points during flag evaluation, using [slog](https://pkg.go.dev/log/slog) structured logging API.
toddbaert marked this conversation as resolved.
Show resolved Hide resolved
This hook can be particularly helpful for troubleshooting and debugging; simply attach it at the global, client or invocation level and ensure your log level is set to "debug".

beeme1mr marked this conversation as resolved.
Show resolved Hide resolved
[logr](https://github.com/go-logr/logr) uses incremental verbosity levels (akin to named levels but in integer form).
The SDK logs `info` at level `0` and `debug` at level `1`. Errors are always logged.
See [hooks](#hooks) for more information on configuring hooks.

### Domains
Clients can be assigned to a domain. A domain is a logical identifier which can be used to associate clients with a particular provider. If a domain has no associated provider, the default provider is used.
Expand Down
37 changes: 3 additions & 34 deletions openfeature/client.go
Original file line number Diff line number Diff line change
Expand Up @@ -41,7 +41,6 @@ type Client struct {
metadata ClientMetadata
hooks []Hook
evaluationContext EvaluationContext
logger logr.Logger

mx sync.RWMutex
}
Expand All @@ -52,25 +51,24 @@ var _ IClient = (*Client)(nil)
// NewClient returns a new Client. Name is a unique identifier for this client
// This helper exists for historical reasons. It is recommended to interact with IEvaluation to derive IClient instances.
func NewClient(name string) *Client {
return newClient(name, api, eventing, logger)
return newClient(name, api, eventing)
}

func newClient(name string, apiRef evaluationImpl, eventRef clientEvent, log logr.Logger) *Client {
func newClient(name string, apiRef evaluationImpl, eventRef clientEvent) *Client {
return &Client{
api: apiRef,
clientEventing: eventRef,
logger: log,
metadata: ClientMetadata{name: name},
hooks: []Hook{},
evaluationContext: EvaluationContext{},
}
}

// Deprecated
toddbaert marked this conversation as resolved.
Show resolved Hide resolved
// WithLogger sets the logger of the client
func (c *Client) WithLogger(l logr.Logger) *Client {
c.mx.Lock()
defer c.mx.Unlock()
c.logger = l
return c
}

Expand Down Expand Up @@ -395,10 +393,6 @@ func (c *Client) BooleanValueDetails(ctx context.Context, flag string, defaultVa
value, ok := evalDetails.Value.(bool)
if !ok {
err := errors.New("evaluated value is not a boolean")
c.logger.Error(
err, "invalid flag resolution type", "expectedType", "boolean",
"gotType", fmt.Sprintf("%T", evalDetails.Value),
)
boolEvalDetails := BooleanEvaluationDetails{
Value: defaultValue,
EvaluationDetails: evalDetails.EvaluationDetails,
Expand Down Expand Up @@ -443,10 +437,6 @@ func (c *Client) StringValueDetails(ctx context.Context, flag string, defaultVal
value, ok := evalDetails.Value.(string)
if !ok {
err := errors.New("evaluated value is not a string")
c.logger.Error(
err, "invalid flag resolution type", "expectedType", "string",
"gotType", fmt.Sprintf("%T", evalDetails.Value),
)
strEvalDetails := StringEvaluationDetails{
Value: defaultValue,
EvaluationDetails: evalDetails.EvaluationDetails,
Expand Down Expand Up @@ -491,10 +481,6 @@ func (c *Client) FloatValueDetails(ctx context.Context, flag string, defaultValu
value, ok := evalDetails.Value.(float64)
if !ok {
err := errors.New("evaluated value is not a float64")
c.logger.Error(
err, "invalid flag resolution type", "expectedType", "float64",
"gotType", fmt.Sprintf("%T", evalDetails.Value),
)
floatEvalDetails := FloatEvaluationDetails{
Value: defaultValue,
EvaluationDetails: evalDetails.EvaluationDetails,
Expand Down Expand Up @@ -539,10 +525,6 @@ func (c *Client) IntValueDetails(ctx context.Context, flag string, defaultValue
value, ok := evalDetails.Value.(int64)
if !ok {
err := errors.New("evaluated value is not an int64")
c.logger.Error(
err, "invalid flag resolution type", "expectedType", "int64",
"gotType", fmt.Sprintf("%T", evalDetails.Value),
)
intEvalDetails := IntEvaluationDetails{
Value: defaultValue,
EvaluationDetails: evalDetails.EvaluationDetails,
Expand Down Expand Up @@ -698,10 +680,6 @@ func (c *Client) evaluate(
evalCtx, err = c.beforeHooks(ctx, hookCtx, apiClientInvocationProviderHooks, evalCtx, options)
hookCtx.evaluationContext = evalCtx
if err != nil {
c.logger.Error(
err, "before hook", "flag", flag, "defaultValue", defaultValue,
"evaluationContext", evalCtx, "evaluationOptions", options, "type", flagType.String(),
)
err = fmt.Errorf("before hook: %w", err)
c.errorHooks(ctx, hookCtx, providerInvocationClientApiHooks, err, options)
return evalDetails, err
Expand Down Expand Up @@ -736,11 +714,6 @@ func (c *Client) evaluate(

err = resolution.Error()
if err != nil {
c.logger.Error(
err, "flag resolution", "flag", flag, "defaultValue", defaultValue,
"evaluationContext", evalCtx, "evaluationOptions", options, "type", flagType.String(), "errorCode", err,
"errMessage", resolution.ResolutionError.message,
)
err = fmt.Errorf("error code: %w", err)
c.errorHooks(ctx, hookCtx, providerInvocationClientApiHooks, err, options)
evalDetails.ResolutionDetail = resolution.ResolutionDetail()
Expand All @@ -751,10 +724,6 @@ func (c *Client) evaluate(
evalDetails.ResolutionDetail = resolution.ResolutionDetail()

if err := c.afterHooks(ctx, hookCtx, providerInvocationClientApiHooks, evalDetails, options); err != nil {
c.logger.Error(
err, "after hook", "flag", flag, "defaultValue", defaultValue,
"evaluationContext", evalCtx, "evaluationOptions", options, "type", flagType.String(),
)
err = fmt.Errorf("after hook: %w", err)
c.errorHooks(ctx, hookCtx, providerInvocationClientApiHooks, err, options)
return evalDetails, err
Expand Down
17 changes: 4 additions & 13 deletions openfeature/event_executor.go
Original file line number Diff line number Diff line change
Expand Up @@ -6,7 +6,8 @@
"sync"
"time"

"github.com/go-logr/logr"
"log/slog"

"golang.org/x/exp/maps"
)

Expand Down Expand Up @@ -37,19 +38,17 @@
activeSubscriptions []providerReference
apiRegistry map[EventType][]EventCallback
scopedRegistry map[string]scopedCallback
logger logr.Logger
eventChan chan eventPayload
once sync.Once
mu sync.Mutex
}

func newEventExecutor(logger logr.Logger) *eventExecutor {
func newEventExecutor() *eventExecutor {
executor := eventExecutor{
namedProviderReference: map[string]providerReference{},
activeSubscriptions: []providerReference{},
apiRegistry: map[EventType][]EventCallback{},
scopedRegistry: map[string]scopedCallback{},
logger: logger,
eventChan: make(chan eventPayload, 5),
}

Expand Down Expand Up @@ -87,14 +86,6 @@
shutdownSemaphore chan interface{}
}

// updateLogger updates the executor's logger
func (e *eventExecutor) updateLogger(l logr.Logger) {
e.mu.Lock()
defer e.mu.Unlock()

e.logger = l
}

// AddHandler adds an API(global) level handler
func (e *eventExecutor) AddHandler(t EventType, c EventCallback) {
e.mu.Lock()
Expand Down Expand Up @@ -377,7 +368,7 @@
go func() {
defer func() {
if r := recover(); r != nil {
e.logger.Info("recovered from a panic")
slog.Info("recovered from a panic")

Check warning on line 371 in openfeature/event_executor.go

View check run for this annotation

Codecov / codecov/patch

openfeature/event_executor.go#L371

Added line #L371 was not covered by tests
}
}()

Expand Down
24 changes: 11 additions & 13 deletions openfeature/event_executor_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -6,13 +6,11 @@ import (
"testing"
"time"

"github.com/go-logr/logr"
"github.com/open-feature/go-sdk/openfeature/internal"
"golang.org/x/exp/slices"
)

func init() {
logger = logr.New(internal.Logger{})

}

// Requirement 5.1.1 The provider MAY define a mechanism for signaling the occurrence of one of a set of events,
Expand All @@ -31,7 +29,7 @@ func TestEventHandler_RegisterUnregisterEventProvider(t *testing.T) {
eventingImpl,
}

executor := newEventExecutor(logger)
executor := newEventExecutor()
err := executor.registerDefaultProvider(eventingProvider)
if err != nil {
t.Fatal(err)
Expand Down Expand Up @@ -1173,7 +1171,7 @@ func TestEventHandler_1ToNMapping(t *testing.T) {
&ProviderEventing{},
}

executor := newEventExecutor(logger)
executor := newEventExecutor()

err := executor.registerDefaultProvider(eventingProvider)
if err != nil {
Expand Down Expand Up @@ -1215,7 +1213,7 @@ func TestEventHandler_1ToNMapping(t *testing.T) {
},
}

executor := newEventExecutor(logger)
executor := newEventExecutor()

err := executor.registerDefaultProvider(eventingProvider)
if err != nil {
Expand Down Expand Up @@ -1266,7 +1264,7 @@ func TestEventHandler_1ToNMapping(t *testing.T) {
},
}

executor := newEventExecutor(logger)
executor := newEventExecutor()

err := executor.registerNamedEventingProvider("clientA", eventingProvider)
if err != nil {
Expand Down Expand Up @@ -1317,7 +1315,7 @@ func TestEventHandler_1ToNMapping(t *testing.T) {
},
}

executor := newEventExecutor(logger)
executor := newEventExecutor()

err := executor.registerNamedEventingProvider("clientA", eventingProvider)
if err != nil {
Expand Down Expand Up @@ -1354,7 +1352,7 @@ func TestEventHandler_1ToNMapping(t *testing.T) {

func TestEventHandler_Registration(t *testing.T) {
t.Run("API handlers", func(t *testing.T) {
executor := newEventExecutor(logger)
executor := newEventExecutor()

// Add multiple - ProviderReady
executor.AddHandler(ProviderReady, &h1)
Expand Down Expand Up @@ -1392,7 +1390,7 @@ func TestEventHandler_Registration(t *testing.T) {
})

t.Run("Client handlers", func(t *testing.T) {
executor := newEventExecutor(logger)
executor := newEventExecutor()

// Add multiple - client a
executor.AddClientHandler("a", ProviderReady, &h1)
Expand Down Expand Up @@ -1429,7 +1427,7 @@ func TestEventHandler_Registration(t *testing.T) {

func TestEventHandler_APIRemoval(t *testing.T) {
t.Run("API level removal", func(t *testing.T) {
executor := newEventExecutor(logger)
executor := newEventExecutor()

// Add multiple - ProviderReady
executor.AddHandler(ProviderReady, &h1)
Expand Down Expand Up @@ -1482,7 +1480,7 @@ func TestEventHandler_APIRemoval(t *testing.T) {
})

t.Run("Client level removal", func(t *testing.T) {
executor := newEventExecutor(logger)
executor := newEventExecutor()

// Add multiple - client a
executor.AddClientHandler("a", ProviderReady, &h1)
Expand Down Expand Up @@ -1539,7 +1537,7 @@ func TestEventHandler_APIRemoval(t *testing.T) {
})

t.Run("remove handlers that were not added", func(t *testing.T) {
executor := newEventExecutor(logger)
executor := newEventExecutor()

// removal of non-added handlers shall not panic
executor.RemoveHandler(ProviderReady, &h1)
Expand Down
97 changes: 97 additions & 0 deletions openfeature/hooks/logging_hook.go
Original file line number Diff line number Diff line change
@@ -0,0 +1,97 @@
package hooks

import (
"context"
"log/slog"

of "github.com/open-feature/go-sdk/openfeature"
)

const (
DOMAIN_KEY = "domain"
PROVIDER_NAME_KEY = "provider_name"
FLAG_KEY_KEY = "flag_key"
DEFAULT_VALUE_KEY = "default_value"
EVALUATION_CONTEXT_KEY = "evaluation_context"
ERROR_CODE_KEY = "error_code"
ERROR_MESSAGE_KEY = "error_message"
REASON_KEY = "reason"
VARIANT_KEY = "variant"
VALUE_KEY = "value"
)

type LoggingHook struct {
includeEvaluationContext bool
logger *slog.Logger
}

func NewLoggingHook(includeEvaluationContext bool) (*LoggingHook, error) {
return NewCustomLoggingHook(slog.Default(), includeEvaluationContext)
}

func NewCustomLoggingHook(logger *slog.Logger, includeEvaluationContext bool) (*LoggingHook, error) {
toddbaert marked this conversation as resolved.
Show resolved Hide resolved
return &LoggingHook{
logger: logger,
includeEvaluationContext: includeEvaluationContext,
}, nil
}

type MarshaledEvaluationContext struct {
TargetingKey string
Attributes map[string]interface{}
}

func (l LoggingHook) buildArgs(hookContext of.HookContext) ([]interface{}, error) {

args := []interface{}{
DOMAIN_KEY, hookContext.ClientMetadata().Domain(),
PROVIDER_NAME_KEY, hookContext.ProviderMetadata().Name,
FLAG_KEY_KEY, hookContext.FlagKey(),
DEFAULT_VALUE_KEY, hookContext.DefaultValue(),
}
if l.includeEvaluationContext {
marshaledEvaluationContext := MarshaledEvaluationContext{
TargetingKey: hookContext.EvaluationContext().TargetingKey(),
Attributes: hookContext.EvaluationContext().Attributes(),
}
args = append(args, EVALUATION_CONTEXT_KEY, marshaledEvaluationContext)
}

return args, nil
}

func (h *LoggingHook) Before(ctx context.Context, hookContext of.HookContext,
hint of.HookHints) (*of.EvaluationContext, error) {
var args, err = h.buildArgs(hookContext)
if err != nil {
return nil, err
}

Check warning on line 68 in openfeature/hooks/logging_hook.go

View check run for this annotation

Codecov / codecov/patch

openfeature/hooks/logging_hook.go#L67-L68

Added lines #L67 - L68 were not covered by tests
h.logger.Debug("Before stage", args...)
return nil, nil
}

func (h *LoggingHook) After(ctx context.Context, hookContext of.HookContext,
flagEvaluationDetails of.InterfaceEvaluationDetails, hookHints of.HookHints) error {
var args, err = h.buildArgs(hookContext)
if err != nil {
return err
}

Check warning on line 78 in openfeature/hooks/logging_hook.go

View check run for this annotation

Codecov / codecov/patch

openfeature/hooks/logging_hook.go#L77-L78

Added lines #L77 - L78 were not covered by tests
args = append(args, REASON_KEY, flagEvaluationDetails.Reason)
args = append(args, VARIANT_KEY, flagEvaluationDetails.Variant)
args = append(args, VALUE_KEY, flagEvaluationDetails.Value)
h.logger.Debug("After stage", args...)
return nil
}

func (h *LoggingHook) Error(ctx context.Context, hookContext of.HookContext, err error, hint of.HookHints) {
args, buildArgsErr := h.buildArgs(hookContext)
if buildArgsErr != nil {
slog.Error("Error building args", "error", buildArgsErr)
}

Check warning on line 90 in openfeature/hooks/logging_hook.go

View check run for this annotation

Codecov / codecov/patch

openfeature/hooks/logging_hook.go#L89-L90

Added lines #L89 - L90 were not covered by tests
args = append(args, ERROR_CODE_KEY, err)
h.logger.Error("Error stage", args...)
}

func (h *LoggingHook) Finally(ctx context.Context, hCtx of.HookContext, hint of.HookHints) {

}
Loading
Loading