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 6 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 @@ import (
"sync"
"time"

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

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

Expand Down Expand Up @@ -37,19 +38,17 @@ type eventExecutor struct {
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 @@ type providerReference struct {
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 @@ func (e *eventExecutor) executeHandler(f func(details EventDetails), event Event
go func() {
defer func() {
if r := recover(); r != nil {
e.logger.Info("recovered from a panic")
slog.Info("recovered from a panic")
}
}()

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
93 changes: 93 additions & 0 deletions openfeature/hooks/logging_hook.go
Original file line number Diff line number Diff line change
@@ -0,0 +1,93 @@
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(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
}
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
}
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) {

Check failure on line 82 in openfeature/hooks/logging_hook.go

View workflow job for this annotation

GitHub Actions / lint

SA4009: argument err is overwritten before first use (staticcheck)
args, err := h.buildArgs(hookContext)

Check failure on line 83 in openfeature/hooks/logging_hook.go

View workflow job for this annotation

GitHub Actions / lint

SA4009(related information): assignment to err (staticcheck)
if err != nil {
slog.Error("Error building args", "error", err)
}
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