feat: implemented structured logging (#54)

* feat: implemented structured logging Signed-off-by: Skye Gill <gill.skye95@gmail.com> * Removed ambiguity from docs. Signed-off-by: Skye Gill <gill.skye95@gmail.com> * Update README.md Co-authored-by: Todd Baert <toddbaert@gmail.com> Signed-off-by: Skye Gill <gill.skye95@gmail.com> Signed-off-by: Skye Gill <gill.skye95@gmail.com> Co-authored-by: Todd Baert <toddbaert@gmail.com>
open-feature · Sep 2, 2022 · 04649c5 · 04649c5
1 parent b8383e1
commit 04649c5
Show file tree

Hide file tree

Showing 11 changed files with 194 additions and 42 deletions.
diff --git a/README.md b/README.md
@@ -28,11 +28,35 @@ import (
 
 func main() {
 	openfeature.SetProvider(openfeature.NoopProvider{})
-	client := openfeature.GetClient("app")
-	value, err := client.BooleanValue("v2_enabled", false, nil)
+	client := openfeature.NewClient("app")
+	value, err := client.BooleanValue("v2_enabled", false, openfeature.EvaluationContext{}, openfeature.EvaluationOptions{})
 }
 ```
 
+## Configuration
+
+### Logging
+
+If not configured, the logger falls back to the standard Go log package at error level only.
+
+In order to avoid coupling to any particular logging implementation the sdk uses the structured logging [logr](https://github.com/go-logr/logr)
+API. This allows integration to any package that implements the layer between their logger and this API.
+Thankfully there is already [integration implementations](https://github.com/go-logr/logr#implementations-non-exhaustive)
+for many of the popular logger packages.
+
+```go
+var l logr.Logger
+l = integratedlogr.New() // replace with your chosen integrator
+
+openfeature.SetLogger(l) // set the logger at global level
+
+c := openfeature.NewClient("log").WithLogger(l) // set the logger at client level
+
+```
+
+[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.
+
 ## Development
 
 ### Installation and Dependencies

diff --git a/go.mod b/go.mod
@@ -6,3 +6,5 @@ require (
 	github.com/golang/mock v1.6.0
 	golang.org/x/text v0.3.7
 )
+
+require github.com/go-logr/logr v1.2.3 // indirect
diff --git a/go.sum b/go.sum
@@ -1,3 +1,5 @@
+github.com/go-logr/logr v1.2.3 h1:2DntVwHkVopvECVRSlL5PSo9eG+cAkDCuckLubN+rq0=
+github.com/go-logr/logr v1.2.3/go.mod h1:jdQByPbusPIv2/zmleS9BjJVeZ6kBagPoEUsqbVz/1A=
 github.com/golang/mock v1.6.0 h1:ErTB+efbowRARo13NNdxyJji2egdxLGQhRaY+DUumQc=
 github.com/golang/mock v1.6.0/go.mod h1:p6yTPP+5HYm5mzsMV8JkE6ZKdX+/wYM6Hr+LicevLPs=
 github.com/yuin/goldmark v1.3.5/go.mod h1:mwnBkeHKe2W/ZEtQ+71ViKU8L12m81fl3OWwC1Zlc8k=

diff --git a/pkg/openfeature/client.go b/pkg/openfeature/client.go
@@ -3,6 +3,8 @@ package openfeature
 import (
 	"errors"
 	"fmt"
+
+	"github.com/go-logr/logr"
 )
 
 // IClient defines the behaviour required of an openfeature client
@@ -38,6 +40,7 @@ type Client struct {
 	metadata          ClientMetadata
 	hooks             []Hook
 	evaluationContext EvaluationContext
+	logger            logr.Logger
 }
 
 // NewClient returns a new Client. Name is a unique identifier for this client
@@ -46,9 +49,16 @@ func NewClient(name string) *Client {
 		metadata:          ClientMetadata{name: name},
 		hooks:             []Hook{},
 		evaluationContext: EvaluationContext{},
+		logger:            api.logger,
 	}
 }
 
+// WithLogger sets the logger of the client
+func (c *Client) WithLogger(l logr.Logger) *Client {
+	c.logger = l
+	return c
+}
+
 // Metadata returns the client's metadata
 func (c Client) Metadata() ClientMetadata {
 	return c.metadata
@@ -57,11 +67,15 @@ func (c Client) Metadata() ClientMetadata {
 // AddHooks appends to the client's collection of any previously added hooks
 func (c *Client) AddHooks(hooks ...Hook) {
 	c.hooks = append(c.hooks, hooks...)
+	c.logger.V(info).Info("appended hooks to client", "client", c.Metadata().name, "hooks", hooks)
 }
 
 // SetEvaluationContext sets the client's evaluation context
 func (c *Client) SetEvaluationContext(evalCtx EvaluationContext) {
 	c.evaluationContext = evalCtx
+	c.logger.V(info).Info(
+		"set client evaluation context", "client", c.Metadata().name, "evaluationContext", evalCtx,
+	)
 }
 
 // EvaluationContext returns the client's evaluation context
@@ -80,6 +94,18 @@ const (
 	Object
 )
 
+func (t Type) String() string {
+	return typeToString[t]
+}
+
+var typeToString = map[Type]string{
+	Boolean: "bool",
+	String:  "string",
+	Float:   "float",
+	Int:     "int",
+	Object:  "object",
+}
+
 type EvaluationDetails struct {
 	FlagKey  string
 	FlagType Type
@@ -88,14 +114,20 @@ type EvaluationDetails struct {
 
 // BooleanValue return boolean evaluation for flag
 func (c Client) BooleanValue(flag string, defaultValue bool, evalCtx EvaluationContext, options EvaluationOptions) (bool, error) {
+
 	evalDetails, err := c.evaluate(flag, Boolean, defaultValue, evalCtx, options)
 	if err != nil {
-		return defaultValue, fmt.Errorf("evaluate: %w", err)
+		return defaultValue, err
 	}
 
 	value, ok := evalDetails.Value.(bool)
 	if !ok {
-		return defaultValue, errors.New("evaluated value is not a boolean")
+		err := errors.New("evaluated value is not a boolean")
+		c.logger.Error(
+			err, "invalid flag resolution type", "expectedType", "bool",
+			"gotType", fmt.Sprintf("%T", evalDetails.Value),
+		)
+		return defaultValue, err
 	}
 
 	return value, nil
@@ -105,12 +137,17 @@ func (c Client) BooleanValue(flag string, defaultValue bool, evalCtx EvaluationC
 func (c Client) StringValue(flag string, defaultValue string, evalCtx EvaluationContext, options EvaluationOptions) (string, error) {
 	evalDetails, err := c.evaluate(flag, String, defaultValue, evalCtx, options)
 	if err != nil {
-		return defaultValue, fmt.Errorf("evaluate: %w", err)
+		return defaultValue, err
 	}
 
 	value, ok := evalDetails.Value.(string)
 	if !ok {
-		return defaultValue, errors.New("evaluated value is not a string")
+		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),
+		)
+		return defaultValue, err
 	}
 
 	return value, nil
@@ -120,12 +157,17 @@ func (c Client) StringValue(flag string, defaultValue string, evalCtx Evaluation
 func (c Client) FloatValue(flag string, defaultValue float64, evalCtx EvaluationContext, options EvaluationOptions) (float64, error) {
 	evalDetails, err := c.evaluate(flag, Float, defaultValue, evalCtx, options)
 	if err != nil {
-		return defaultValue, fmt.Errorf("evaluate: %w", err)
+		return defaultValue, err
 	}
 
 	value, ok := evalDetails.Value.(float64)
 	if !ok {
-		return defaultValue, errors.New("evaluated value is not a float64")
+		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),
+		)
+		return defaultValue, err
 	}
 
 	return value, nil
@@ -135,12 +177,17 @@ func (c Client) FloatValue(flag string, defaultValue float64, evalCtx Evaluation
 func (c Client) IntValue(flag string, defaultValue int64, evalCtx EvaluationContext, options EvaluationOptions) (int64, error) {
 	evalDetails, err := c.evaluate(flag, Int, defaultValue, evalCtx, options)
 	if err != nil {
-		return defaultValue, fmt.Errorf("evaluate: %w", err)
+		return defaultValue, err
 	}
 
 	value, ok := evalDetails.Value.(int64)
 	if !ok {
-		return defaultValue, errors.New("evaluated value is not an int64")
+		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),
+		)
+		return defaultValue, err
 	}
 
 	return value, nil
@@ -180,6 +227,10 @@ func (c Client) ObjectValueDetails(flag string, defaultValue interface{}, evalCt
 func (c Client) evaluate(
 	flag string, flagType Type, defaultValue interface{}, evalCtx EvaluationContext, options EvaluationOptions,
 ) (EvaluationDetails, error) {
+	c.logger.V(debug).Info(
+		"evaluating flag", "flag", flag, "type", flagType.String(), "defaultValue", defaultValue,
+		"evaluationContext", evalCtx, "evaluationOptions", options,
+	)
 	evalCtx = mergeContexts(evalCtx, c.evaluationContext, api.evaluationContext) // API (global) -> client -> invocation
 
 	var err error
@@ -208,7 +259,11 @@ func (c Client) evaluate(
 	evalCtx, err = c.beforeHooks(hookCtx, apiClientInvocationProviderHooks, evalCtx, options)
 	hookCtx.evaluationContext = evalCtx
 	if err != nil {
-		err = fmt.Errorf("execute before hook: %w", err)
+		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(hookCtx, providerInvocationClientApiHooks, err, options)
 		return evalDetails, err
 	}
@@ -238,7 +293,11 @@ func (c Client) evaluate(
 
 	err = resolution.Error()
 	if err != nil {
-		err = fmt.Errorf("evaluate the flag: %w", err)
+		c.logger.Error(
+			err, "flag resolution", "flag", flag, "defaultValue", defaultValue,
+			"evaluationContext", evalCtx, "evaluationOptions", options, "type", flagType.String(), "errorCode", err,
+		)
+		err = fmt.Errorf("error code: %w", err)
 		c.errorHooks(hookCtx, providerInvocationClientApiHooks, err, options)
 		return evalDetails, err
 	}
@@ -247,11 +306,16 @@ func (c Client) evaluate(
 	}
 
 	if err := c.afterHooks(hookCtx, providerInvocationClientApiHooks, evalDetails, options); err != nil {
-		err = fmt.Errorf("execute after hook: %w", err)
+		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(hookCtx, providerInvocationClientApiHooks, err, options)
 		return evalDetails, err
 	}
 
+	c.logger.V(debug).Info("evaluated flag", "flag", flag, "details", evalDetails, "type", flagType)
 	return evalDetails, nil
 }
 
@@ -269,6 +333,9 @@ func flattenContext(evalCtx EvaluationContext) map[string]interface{} {
 func (c Client) beforeHooks(
 	hookCtx HookContext, hooks []Hook, evalCtx EvaluationContext, options EvaluationOptions,
 ) (EvaluationContext, error) {
+	c.logger.V(debug).Info("executing before hooks")
+	defer c.logger.V(debug).Info("executed before hooks")
+
 	for _, hook := range hooks {
 		resultEvalCtx, err := hook.Before(hookCtx, options.hookHints)
 		if resultEvalCtx != nil {
@@ -285,6 +352,9 @@ func (c Client) beforeHooks(
 func (c Client) afterHooks(
 	hookCtx HookContext, hooks []Hook, evalDetails EvaluationDetails, options EvaluationOptions,
 ) error {
+	c.logger.V(debug).Info("executing after hooks")
+	defer c.logger.V(debug).Info("executed after hooks")
+
 	for _, hook := range hooks {
 		if err := hook.After(hookCtx, evalDetails, options.hookHints); err != nil {
 			return err
@@ -295,12 +365,18 @@ func (c Client) afterHooks(
 }
 
 func (c Client) errorHooks(hookCtx HookContext, hooks []Hook, err error, options EvaluationOptions) {
+	c.logger.V(debug).Info("executing error hooks")
+	defer c.logger.V(debug).Info("executed error hooks")
+
 	for _, hook := range hooks {
 		hook.Error(hookCtx, err, options.hookHints)
 	}
 }
 
 func (c Client) finallyHooks(hookCtx HookContext, hooks []Hook, options EvaluationOptions) {
+	c.logger.V(debug).Info("executing finally hooks")
+	defer c.logger.V(debug).Info("executed finally hooks")
+
 	for _, hook := range hooks {
 		hook.Finally(hookCtx, options.hookHints)
 	}

diff --git a/pkg/openfeature/client_test.go b/pkg/openfeature/client_test.go
@@ -218,7 +218,7 @@ func TestRequirement_1_4_9(t *testing.T) {
 		defer t.Cleanup(initSingleton)
 		mockProvider := NewMockFeatureProvider(ctrl)
 		defaultValue := true
-		mockProvider.EXPECT().Metadata().Times(2)
+		mockProvider.EXPECT().Metadata().AnyTimes()
 		mockProvider.EXPECT().Hooks().AnyTimes()
 		mockProvider.EXPECT().BooleanEvaluation(flagKey, defaultValue, flatCtx).
 			Return(BoolResolutionDetail{
@@ -254,7 +254,7 @@ func TestRequirement_1_4_9(t *testing.T) {
 		defer t.Cleanup(initSingleton)
 		mockProvider := NewMockFeatureProvider(ctrl)
 		defaultValue := "default"
-		mockProvider.EXPECT().Metadata().Times(2)
+		mockProvider.EXPECT().Metadata().AnyTimes()
 		mockProvider.EXPECT().Hooks().AnyTimes()
 		mockProvider.EXPECT().StringEvaluation(flagKey, defaultValue, flatCtx).
 			Return(StringResolutionDetail{
@@ -290,7 +290,7 @@ func TestRequirement_1_4_9(t *testing.T) {
 		defer t.Cleanup(initSingleton)
 		mockProvider := NewMockFeatureProvider(ctrl)
 		defaultValue := 3.14159
-		mockProvider.EXPECT().Metadata().Times(2)
+		mockProvider.EXPECT().Metadata().AnyTimes()
 		mockProvider.EXPECT().Hooks().AnyTimes()
 		mockProvider.EXPECT().FloatEvaluation(flagKey, defaultValue, flatCtx).
 			Return(FloatResolutionDetail{
@@ -326,7 +326,7 @@ func TestRequirement_1_4_9(t *testing.T) {
 		defer t.Cleanup(initSingleton)
 		mockProvider := NewMockFeatureProvider(ctrl)
 		var defaultValue int64 = 3
-		mockProvider.EXPECT().Metadata().Times(2)
+		mockProvider.EXPECT().Metadata().AnyTimes()
 		mockProvider.EXPECT().Hooks().AnyTimes()
 		mockProvider.EXPECT().IntEvaluation(flagKey, defaultValue, flatCtx).
 			Return(IntResolutionDetail{
@@ -365,7 +365,7 @@ func TestRequirement_1_4_9(t *testing.T) {
 			foo string
 		}
 		defaultValue := obj{foo: "bar"}
-		mockProvider.EXPECT().Metadata().Times(2)
+		mockProvider.EXPECT().Metadata().AnyTimes()
 		mockProvider.EXPECT().Hooks().AnyTimes()
 		mockProvider.EXPECT().ObjectEvaluation(flagKey, defaultValue, flatCtx).
 			Return(ResolutionDetail{
@@ -420,8 +420,8 @@ func TestClient_ProviderEvaluationReturnsUnexpectedType(t *testing.T) {
 		defer t.Cleanup(initSingleton)
 		ctrl := gomock.NewController(t)
 		mockProvider := NewMockFeatureProvider(ctrl)
+		mockProvider.EXPECT().Metadata().AnyTimes()
 		SetProvider(mockProvider)
-		mockProvider.EXPECT().Metadata()
 		mockProvider.EXPECT().Hooks().AnyTimes()
 		mockProvider.EXPECT().BooleanEvaluation(gomock.Any(), gomock.Any(), gomock.Any()).
 			Return(BoolResolutionDetail{ResolutionDetail: ResolutionDetail{Value: 3}})
@@ -436,8 +436,8 @@ func TestClient_ProviderEvaluationReturnsUnexpectedType(t *testing.T) {
 		defer t.Cleanup(initSingleton)
 		ctrl := gomock.NewController(t)
 		mockProvider := NewMockFeatureProvider(ctrl)
+		mockProvider.EXPECT().Metadata().AnyTimes()
 		SetProvider(mockProvider)
-		mockProvider.EXPECT().Metadata()
 		mockProvider.EXPECT().Hooks().AnyTimes()
 		mockProvider.EXPECT().StringEvaluation(gomock.Any(), gomock.Any(), gomock.Any()).
 			Return(StringResolutionDetail{ResolutionDetail: ResolutionDetail{Value: 3}})
@@ -452,8 +452,8 @@ func TestClient_ProviderEvaluationReturnsUnexpectedType(t *testing.T) {
 		defer t.Cleanup(initSingleton)
 		ctrl := gomock.NewController(t)
 		mockProvider := NewMockFeatureProvider(ctrl)
+		mockProvider.EXPECT().Metadata().AnyTimes()
 		SetProvider(mockProvider)
-		mockProvider.EXPECT().Metadata()
 		mockProvider.EXPECT().Hooks().AnyTimes()
 		mockProvider.EXPECT().FloatEvaluation(gomock.Any(), gomock.Any(), gomock.Any()).
 			Return(FloatResolutionDetail{ResolutionDetail: ResolutionDetail{Value: false}})
@@ -468,8 +468,8 @@ func TestClient_ProviderEvaluationReturnsUnexpectedType(t *testing.T) {
 		defer t.Cleanup(initSingleton)
 		ctrl := gomock.NewController(t)
 		mockProvider := NewMockFeatureProvider(ctrl)
+		mockProvider.EXPECT().Metadata().AnyTimes()
 		SetProvider(mockProvider)
-		mockProvider.EXPECT().Metadata()
 		mockProvider.EXPECT().Hooks().AnyTimes()
 		mockProvider.EXPECT().IntEvaluation(gomock.Any(), gomock.Any(), gomock.Any()).
 			Return(IntResolutionDetail{ResolutionDetail: ResolutionDetail{Value: false}})

diff --git a/pkg/openfeature/evaluation_context.go b/pkg/openfeature/evaluation_context.go
@@ -3,6 +3,6 @@ package openfeature
 // EvaluationContext
 // https://github.com/open-feature/spec/blob/main/specification/evaluation-context/evaluation-context.md
 type EvaluationContext struct {
-	TargetingKey string // uniquely identifying the subject (end-user, or client service) of a flag evaluation
-	Attributes map[string]interface{}
+	TargetingKey string                 `json:"targetingKey"` // uniquely identifying the subject (end-user, or client service) of a flag evaluation
+	Attributes   map[string]interface{} `json:"attributes"`
 }