fix(logs): Fixing log messages for Targeted Rollouts and feature variable evaluation.

pkg/client/client.go

@@ -350,9 +350,16 @@ func (o *OptimizelyClient) getFeatureVariable(featureKey, variableKey string, us
 	variable := featureDecisionContext.Variable
 
 	if featureDecision.Variation != nil {
-		if v, ok := featureDecision.Variation.Variables[variable.ID]; ok && featureDecision.Variation.FeatureEnabled {
-			return v.Value, variable.Type, &featureDecision, nil
+		if featureDecision.Variation.FeatureEnabled {
+			if v, ok := featureDecision.Variation.Variables[variable.ID]; ok {
+				o.logger.Debug(fmt.Sprintf(logging.VariableValueForFeatureFlag.String(), v.Value, variable.Key, featureKey))
+				return v.Value, variable.Type, &featureDecision, nil
+			}
+		} else {
+			o.logger.Debug(fmt.Sprintf(logging.FeatureNotEnabledForUserReturningDefault.String(), featureKey, userContext.ID, variable.DefaultValue))
 		}
+	} else {
+		o.logger.Debug(fmt.Sprintf(logging.ReturningDefaultValue.String(), userContext.ID, variableKey, featureKey))
 	}
 
 	return variable.DefaultValue, variable.Type, &featureDecision, nil
@@ -411,6 +418,13 @@ func (o *OptimizelyClient) GetAllFeatureVariablesWithDecision(featureKey string,
 
 	if featureDecision.Variation != nil {
 		enabled = featureDecision.Variation.FeatureEnabled
+		if enabled {
+			o.logger.Debug(fmt.Sprintf(logging.FeatureEnabledForUser.String(), featureKey, userContext.ID))
+		} else {
+			o.logger.Debug(fmt.Sprintf(logging.FeatureNotEnabledForUser.String(), featureKey, userContext.ID))
+		}
+	} else {
+		o.logger.Debug(fmt.Sprintf(logging.ReturningAllDefaultValue.String(), userContext.ID, featureKey))
 	}
 
 	feature := decisionContext.Feature
@@ -427,6 +441,7 @@ func (o *OptimizelyClient) GetAllFeatureVariablesWithDecision(featureKey string,
 		if enabled {
 			if variable, ok := featureDecision.Variation.Variables[v.ID]; ok {
 				val = variable.Value
+				o.logger.Debug(fmt.Sprintf(logging.VariableValueForFeatureFlag.String(), val, v.Key, featureKey))
 			}
 		}
 

pkg/decision/bucketer/experiment_bucketer.go

@@ -1,5 +1,5 @@
 /****************************************************************************
- * Copyright 2019, Optimizely, Inc. and contributors                        *
+ * Copyright 2019-2020, Optimizely, Inc. and contributors                   *
  *                                                                          *
  * Licensed under the Apache License, Version 2.0 (the "License");          *
  * you may not use this file except in compliance with the License.         *
@@ -18,6 +18,8 @@
 package bucketer
 
 import (
+	"fmt"
+
 	"github.com/optimizely/go-sdk/pkg/decision/reasons"
 	"github.com/optimizely/go-sdk/pkg/entities"
 	"github.com/optimizely/go-sdk/pkg/logging"
@@ -31,28 +33,34 @@ type ExperimentBucketer interface {
 // MurmurhashExperimentBucketer buckets the user using the mmh3 algorightm
 type MurmurhashExperimentBucketer struct {
 	bucketer Bucketer
+	logger   logging.OptimizelyLogProducer
 }
 
 // NewMurmurhashExperimentBucketer returns a new instance of the murmurhash experiment bucketer
 func NewMurmurhashExperimentBucketer(logger logging.OptimizelyLogProducer, hashSeed uint32) *MurmurhashExperimentBucketer {
 	return &MurmurhashExperimentBucketer{
-		bucketer: MurmurhashBucketer{hashSeed: hashSeed, logger:logger},
+		bucketer: MurmurhashBucketer{hashSeed: hashSeed, logger: logger},
+		logger:   logger,
 	}
 }
 
 // Bucket buckets the user into the given experiment
 func (b MurmurhashExperimentBucketer) Bucket(bucketingID string, experiment entities.Experiment, group entities.Group) (*entities.Variation, reasons.Reason, error) {
 	if experiment.GroupID != "" && group.Policy == "random" {
-		bucketKey := bucketingID + group.ID
-		bucketedExperimentID := b.bucketer.BucketToEntity(bucketKey, group.TrafficAllocation)
-		if bucketedExperimentID == "" || bucketedExperimentID != experiment.ID {
-			// User is not bucketed into provided experiment in mutex group
+		if bucketedExperimentID := b.bucketer.BucketToEntity(bucketingID, group.ID, group.TrafficAllocation); bucketedExperimentID != "" {
+			if bucketedExperimentID != experiment.ID {
+				// User is not bucketed into provided experiment in mutex group
+				b.logger.Debug(fmt.Sprintf(logging.UserNotBucketedIntoExperimentInGroup.String(), bucketingID, experiment.Key, group.ID))
+				return nil, reasons.NotBucketedIntoVariation, nil
+			}
+			b.logger.Debug(fmt.Sprintf(logging.UserBucketedIntoExperimentInGroup.String(), bucketingID, experiment.Key, group.ID))
+		} else {
+			b.logger.Debug(fmt.Sprintf(logging.UserNotBucketedIntoAnyExperimentInGroup.String(), bucketingID, group.ID))
 			return nil, reasons.NotBucketedIntoVariation, nil
 		}
 	}
 
-	bucketKey := bucketingID + experiment.ID
-	bucketedVariationID := b.bucketer.BucketToEntity(bucketKey, experiment.TrafficAllocation)
+	bucketedVariationID := b.bucketer.BucketToEntity(bucketingID, experiment.ID, experiment.TrafficAllocation)
 	if bucketedVariationID == "" {
 		// User is not bucketed into a variation in the experiment, return nil variation
 		return nil, reasons.NotBucketedIntoVariation, nil

pkg/decision/bucketer/experiment_bucketer_test.go

@@ -1,39 +1,79 @@
+/****************************************************************************
+ * Copyright 2019-2020, Optimizely, Inc. and contributors                   *
+ *                                                                          *
+ * Licensed under the Apache License, Version 2.0 (the "License");          *
+ * you may not use this file except in compliance with the License.         *
+ * You may obtain a copy of the License at                                  *
+ *                                                                          *
+ *    http://www.apache.org/licenses/LICENSE-2.0                            *
+ *                                                                          *
+ * Unless required by applicable law or agreed to in writing, software      *
+ * distributed under the License is distributed on an "AS IS" BASIS,        *
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. *
+ * See the License for the specific language governing permissions and      *
+ * limitations under the License.                                           *
+ ***************************************************************************/
+
+// Package bucketer //
 package bucketer
 
 import (
-	"github.com/optimizely/go-sdk/pkg/logging"
+	"fmt"
 	"testing"
 
 	"github.com/optimizely/go-sdk/pkg/decision/reasons"
+	"github.com/optimizely/go-sdk/pkg/logging"
 
 	"github.com/optimizely/go-sdk/pkg/entities"
 	"github.com/stretchr/testify/assert"
+	"github.com/stretchr/testify/mock"
 )
 
+type MockLogger struct {
+	mock.Mock
+}
+
+func (m *MockLogger) Debug(message string) {
+	m.Called(message)
+}
+
+func (m *MockLogger) Info(message string) {
+	m.Called(message)
+}
+
+func (m *MockLogger) Warning(message string) {
+	m.Called(message)
+}
+
+func (m *MockLogger) Error(message string, err interface{}) {
+	m.Called(message, err)
+}
+
 func TestBucketExclusionGroups(t *testing.T) {
+	mockLogger := MockLogger{}
 	experiment1 := entities.Experiment{
 		ID:  "1886780721",
 		Key: "experiment_1",
 		Variations: map[string]entities.Variation{
-			"22222": entities.Variation{ID: "22222", Key: "exp_1_var_1"},
-			"22223": entities.Variation{ID: "22223", Key: "exp_1_var_2"},
+			"22222": {ID: "22222", Key: "exp_1_var_1"},
+			"22223": {ID: "22223", Key: "exp_1_var_2"},
 		},
 		TrafficAllocation: []entities.Range{
-			entities.Range{EntityID: "22222", EndOfRange: 4999},
-			entities.Range{EntityID: "22223", EndOfRange: 10000},
+			{EntityID: "22222", EndOfRange: 4999},
+			{EntityID: "22223", EndOfRange: 10000},
 		},
 		GroupID: "1886780722",
 	}
 	experiment2 := entities.Experiment{
 		ID:  "1886780723",
 		Key: "experiment_2",
 		Variations: map[string]entities.Variation{
-			"22224": entities.Variation{ID: "22224", Key: "exp_2_var_1"},
-			"22225": entities.Variation{ID: "22225", Key: "exp_2_var_2"},
+			"22224": {ID: "22224", Key: "exp_2_var_1"},
+			"22225": {ID: "22225", Key: "exp_2_var_2"},
 		},
 		TrafficAllocation: []entities.Range{
-			entities.Range{EntityID: "22224", EndOfRange: 4999},
-			entities.Range{EntityID: "22225", EndOfRange: 10000},
+			{EntityID: "22224", EndOfRange: 4999},
+			{EntityID: "22225", EndOfRange: 10000},
 		},
 		GroupID: "1886780722",
 	}
@@ -42,13 +82,18 @@ func TestBucketExclusionGroups(t *testing.T) {
 		ID:     "1886780722",
 		Policy: "random",
 		TrafficAllocation: []entities.Range{
-			entities.Range{EntityID: "1886780721", EndOfRange: 2500},
-			entities.Range{EntityID: "1886780723", EndOfRange: 5000},
+			{EntityID: "1886780721", EndOfRange: 2500},
+			{EntityID: "1886780723", EndOfRange: 5000},
 		},
 	}
 
-	bucketer := NewMurmurhashExperimentBucketer(logging.GetLogger("","TestBucketExclusionGroups" ), DefaultHashSeed)
+	bucketer := NewMurmurhashExperimentBucketer(&mockLogger, DefaultHashSeed)
 	// ppid2 + 1886780722 (groupId) will generate bucket value of 2434 which maps to experiment 1
+	mockLogger.On("Debug", fmt.Sprintf(logging.UserAssignedToBucketValue.String(), 2434, "ppid2"))
+	mockLogger.On("Debug", fmt.Sprintf(logging.UserBucketedIntoExperimentInGroup.String(), "ppid2", "experiment_1", "1886780722"))
+	mockLogger.On("Debug", fmt.Sprintf(logging.UserAssignedToBucketValue.String(), 4299, "ppid2"))
+	mockLogger.On("Debug", fmt.Sprintf(logging.UserNotBucketedIntoExperimentInGroup.String(), "ppid2", "experiment_2", "1886780722"))
+
 	bucketedVariation, reason, _ := bucketer.Bucket("ppid2", experiment1, exclusionGroup)
 	assert.Equal(t, experiment1.Variations["22222"], *bucketedVariation)
 	assert.Equal(t, reasons.BucketedIntoVariation, reason)

pkg/decision/bucketer/murmurhashbucketer.go

@@ -1,5 +1,5 @@
 /****************************************************************************
- * Copyright 2019, Optimizely, Inc. and contributors                        *
+ * Copyright 2019-2020, Optimizely, Inc. and contributors                   *
  *                                                                          *
  * Licensed under the Apache License, Version 2.0 (the "License");          *
  * you may not use this file except in compliance with the License.         *
@@ -36,7 +36,7 @@ const maxTrafficValue = 10000
 // Bucketer is used to generate bucket value using bucketing key
 type Bucketer interface {
 	Generate(bucketingKey string) int
-	BucketToEntity(bucketKey string, trafficAllocations []entities.Range) (entityID string)
+	BucketToEntity(bucketingID, entityID string, trafficAllocations []entities.Range) string
 }
 
 // MurmurhashBucketer generates the bucketing value using the mmh3 algorightm
@@ -49,7 +49,7 @@ type MurmurhashBucketer struct {
 func NewMurmurhashBucketer(logger logging.OptimizelyLogProducer, hashSeed uint32) *MurmurhashBucketer {
 	return &MurmurhashBucketer{
 		hashSeed: hashSeed,
-		logger: logger,
+		logger:   logger,
 	}
 }
 
@@ -64,10 +64,10 @@ func (b MurmurhashBucketer) Generate(bucketingKey string) int {
 	return int(ratio * maxTrafficValue)
 }
 
-// BucketToEntity buckets into a traffic against given bucketKey
-func (b MurmurhashBucketer) BucketToEntity(bucketKey string, trafficAllocations []entities.Range) (entityID string) {
-	bucketValue := b.Generate(bucketKey)
-
+// BucketToEntity buckets into a traffic against given bucketingId and entityID
+func (b MurmurhashBucketer) BucketToEntity(bucketingID, entityID string, trafficAllocations []entities.Range) string {
+	bucketValue := b.Generate(bucketingID + entityID)
+	b.logger.Debug(fmt.Sprintf(logging.UserAssignedToBucketValue.String(), bucketValue, bucketingID))
 	var currentEndOfRange int
 	for _, trafficAllocationRange := range trafficAllocations {
 		currentEndOfRange = trafficAllocationRange.EndOfRange

pkg/decision/bucketer/murmurhashbucketer_test.go

@@ -1,10 +1,28 @@
+/****************************************************************************
+ * Copyright 2019-2020, Optimizely, Inc. and contributors                   *
+ *                                                                          *
+ * Licensed under the Apache License, Version 2.0 (the "License");          *
+ * you may not use this file except in compliance with the License.         *
+ * You may obtain a copy of the License at                                  *
+ *                                                                          *
+ *    http://www.apache.org/licenses/LICENSE-2.0                            *
+ *                                                                          *
+ * Unless required by applicable law or agreed to in writing, software      *
+ * distributed under the License is distributed on an "AS IS" BASIS,        *
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. *
+ * See the License for the specific language governing permissions and      *
+ * limitations under the License.                                           *
+ ***************************************************************************/
+
+// Package bucketer //
 package bucketer
 
 import (
 	"fmt"
-	"github.com/optimizely/go-sdk/pkg/logging"
 	"testing"
 
+	"github.com/optimizely/go-sdk/pkg/logging"
+
 	"github.com/optimizely/go-sdk/pkg/entities"
 	"github.com/stretchr/testify/assert"
 )
@@ -16,13 +34,11 @@ func TestBucketToEntity(t *testing.T) {
 	experimentID2 := "1886780722"
 
 	// bucket value 5254
-	bucketingKey1 := fmt.Sprintf("%s%s", "ppid1", experimentID)
+	bucketingID1 := "ppid1"
 	// bucket value 4299
-	bucketingKey2 := fmt.Sprintf("%s%s", "ppid2", experimentID)
+	bucketingID2 := "ppid2"
 	// bucket value 2434
-	bucketingKey3 := fmt.Sprintf("%s%s", "ppid2", experimentID2)
-	// bucket value 5439
-	bucketingKey4 := fmt.Sprintf("%s%s", "ppid3", experimentID)
+	bucketingID3 := "ppid3"
 
 	variation1 := "1234567123"
 	variation2 := "5949300123"
@@ -41,14 +57,14 @@ func TestBucketToEntity(t *testing.T) {
 		},
 	}
 
-	assert.Equal(t, variation2, bucketer.BucketToEntity(bucketingKey1, trafficAlloc))
-	assert.Equal(t, variation1, bucketer.BucketToEntity(bucketingKey2, trafficAlloc))
+	assert.Equal(t, variation2, bucketer.BucketToEntity(bucketingID1, experimentID, trafficAlloc))
+	assert.Equal(t, variation1, bucketer.BucketToEntity(bucketingID2, experimentID, trafficAlloc))
 
 	// bucket to empty variation range
-	assert.Equal(t, "", bucketer.BucketToEntity(bucketingKey3, trafficAlloc))
+	assert.Equal(t, "", bucketer.BucketToEntity(bucketingID2, experimentID2, trafficAlloc))
 
 	// bucket outside of range (not in experiment)
-	assert.Equal(t, "", bucketer.BucketToEntity(bucketingKey4, trafficAlloc))
+	assert.Equal(t, "", bucketer.BucketToEntity(bucketingID3, experimentID, trafficAlloc))
 }
 
 func TestGenerateBucketValue(t *testing.T) {

pkg/decision/evaluator/condition_test.go

@@ -136,7 +136,7 @@ func (s *ConditionTestSuite) TestCustomAttributeConditionEvaluatorWithUnknownTyp
 	s.mockLogger.AssertExpectations(s.T())
 }
 
-func (s *ConditionTestSuite)  TestCustomAttributeConditionEvaluatorForGeSemver() {
+func (s *ConditionTestSuite) TestCustomAttributeConditionEvaluatorForGeSemver() {
 	conditionEvaluator := CustomAttributeConditionEvaluator{}
 	condition := entities.Condition{
 		Match: "semver_ge",
@@ -154,10 +154,10 @@ func (s *ConditionTestSuite)  TestCustomAttributeConditionEvaluatorForGeSemver()
 
 	condTreeParams := entities.NewTreeParameters(&user, map[string]entities.Audience{})
 	result, _ := conditionEvaluator.Evaluate(condition, condTreeParams)
-	s.Equal( result, true)
+	s.Equal(result, true)
 }
 
-func (s *ConditionTestSuite)  TestCustomAttributeConditionEvaluatorForGeSemverBeta() {
+func (s *ConditionTestSuite) TestCustomAttributeConditionEvaluatorForGeSemverBeta() {
 	conditionEvaluator := CustomAttributeConditionEvaluator{}
 	condition := entities.Condition{
 		Match: "semver_ge",
@@ -178,7 +178,7 @@ func (s *ConditionTestSuite)  TestCustomAttributeConditionEvaluatorForGeSemverBe
 	s.Equal(true, result)
 }
 
-func (s *ConditionTestSuite)  TestCustomAttributeConditionEvaluatorForGeSemverInvalid() {
+func (s *ConditionTestSuite) TestCustomAttributeConditionEvaluatorForGeSemverInvalid() {
 	conditionEvaluator := CustomAttributeConditionEvaluator{}
 	condition := entities.Condition{
 		Match: "semver_ge",

pkg/decision/evaluator/matchers/lt_test.go

@@ -50,7 +50,6 @@ func (s *LtTestSuite) TestLtMatcherInt() {
 			"int_42": 41,
 		},
 	}
-
 	result, err := s.matcher(condition, user, s.mockLogger)
 	s.NoError(err)
 	s.True(result)
@@ -125,7 +124,6 @@ func (s *LtTestSuite) TestLtMatcherFloat() {
 			"float_4_2": 4,
 		},
 	}
-
 	result, err := s.matcher(condition, user, s.mockLogger)
 	s.NoError(err)
 	s.True(result)
@@ -136,7 +134,6 @@ func (s *LtTestSuite) TestLtMatcherFloat() {
 			"float_4_2": 4.19999,
 		},
 	}
-
 	result, err = s.matcher(condition, user, s.mockLogger)
 	s.NoError(err)
 	s.True(result)

pkg/decision/experiment_bucketer_service.go

@@ -80,6 +80,11 @@ func (s ExperimentBucketerService) GetDecision(decisionContext ExperimentDecisio
 	}
 	// @TODO: handle error from bucketer
 	variation, reason, _ := s.bucketer.Bucket(bucketingID, *experiment, group)
+	if variation != nil {
+		s.logger.Debug(fmt.Sprintf(logging.UserBucketedIntoVariationInExperiment.String(), userContext.ID, variation.Key, experiment.Key))
+	} else {
+		s.logger.Debug(fmt.Sprintf(logging.UserNotBucketedIntoVariation.String(), userContext.ID))
+	}
 	experimentDecision.Reason = reason
 	experimentDecision.Variation = variation
 	return experimentDecision, nil

pkg/decision/experiment_bucketer_service_test.go

@@ -88,6 +88,8 @@ func (s *ExperimentBucketerTestSuite) TestGetDecisionNoTargeting() {
 	}
 	s.mockBucketer.On("Bucket", testUserContext.ID, testExp1111, entities.Group{}).Return(&testExp1111Var2222, reasons.BucketedIntoVariation, nil)
 	s.mockLogger.On("Debug", fmt.Sprintf(logging.ExperimentAudiencesEvaluatedTo.String(), "test_experiment_1111", true))
+	s.mockLogger.On("Debug", fmt.Sprintf(logging.UserBucketedIntoVariationInExperiment.String(), "test_user_1", "2222", "test_experiment_1111"))
+
 	experimentBucketerService := ExperimentBucketerService{
 		bucketer: s.mockBucketer,
 		logger:   s.mockLogger,
@@ -121,6 +123,7 @@ func (s *ExperimentBucketerTestSuite) TestGetDecisionWithTargetingPasses() {
 	s.mockConfig.On("GetAudienceMap").Return(map[string]entities.Audience{})
 	s.mockLogger.On("Debug", fmt.Sprintf(logging.EvaluatingAudiencesForExperiment.String(), "test_targeted_experiment_1116"))
 	s.mockLogger.On("Debug", fmt.Sprintf(logging.ExperimentAudiencesEvaluatedTo.String(), "test_targeted_experiment_1116", true))
+	s.mockLogger.On("Debug", fmt.Sprintf(logging.UserBucketedIntoVariationInExperiment.String(), "test_user_1", "2228", "test_targeted_experiment_1116"))
 
 	testDecisionContext := ExperimentDecisionContext{
 		Experiment:    &testTargetedExp1116,