feat(Audience Evaluation): Audience Logging #156

oakbani · 2019-01-02T13:36:13Z

Summary

This adds logging for audience evaluation.

Test plan

Unit tests written in

test_condition.py
test_audience.py

Issues

OASIS-3850

coveralls · 2019-01-02T13:43:01Z

Coverage decreased (-0.06%) to 99.635% when pulling 691c439 on oakbani/logging-for-audience into 2c35eb8 on master.

coveralls · 2019-01-02T13:43:01Z

Coverage decreased (-0.06%) to 99.635% when pulling 691c439 on oakbani/logging-for-audience into 2c35eb8 on master.

coveralls · 2019-01-02T13:43:01Z

Coverage decreased (-0.06%) to 99.635% when pulling 691c439 on oakbani/logging-for-audience into 2c35eb8 on master.

coveralls · 2019-01-02T13:43:01Z

Coverage decreased (-0.06%) to 99.635% when pulling 691c439 on oakbani/logging-for-audience into 2c35eb8 on master.

coveralls · 2019-01-02T13:43:01Z

Coverage decreased (-0.06%) to 99.635% when pulling 691c439 on oakbani/logging-for-audience into 2c35eb8 on master.

coveralls · 2019-01-02T13:43:02Z

Coverage increased (+0.02%) to 99.707% when pulling 3d0bfee on oakbani/logging-for-audience into a3b46a2 on master.

oakbani · 2019-01-02T13:52:42Z

optimizely/helpers/audience.py

  if audience_conditions is None or audience_conditions == []:
+    logger.info(logs.NO_AUDIENCE_ATTACHED.format(


Added to log why it evaluates to True in this case. Not in doc

Interesting idea to specifically mention the "no audiences" case. But to reduce the number of types of log messages, and to increase consistency with other SDKs, can we find a way to rely on the EVALUATING_AUDIENCES and AUDIENCE_EVALUATION_RESULT_COMBINED messages instead?

oakbani · 2019-01-02T13:53:54Z

optimizely/helpers/audience.py

+    json.dumps(audience_conditions)
+  ))
+
+  logger.debug(logs.USER_ATTRIBUTES.format(json.dumps(attributes)))


The doc sort of suggests that we log attributes with every audience evaluation. I have logged it here at top-level since attributes remain same irrespective of audience conditions

oakbani · 2019-01-02T13:55:32Z

optimizely/helpers/condition.py

-       not validator.are_values_same_type(condition_value, user_value):
-        return None
+    if not validator.are_values_same_type(condition_value, user_value):
+      self.logger.debug(logs.MISMATCH_TYPE.format(


Added this log to distinguish exactly what is inapplicable and what is type mismatch for exact evaluator.
Not in docs.
For exact, user value {}, [], () are inapplicable but integer 5 is a mismatch if condition value is a string

oakbani · 2019-01-02T13:57:01Z

tests/helpers_tests/test_condition.py

+    self.mock_client_logger = mock.MagicMock()
+
+  def test_evaluate__match_type__invalid(self):
+    log_level = 'warning'


Added log_level variable in every testcase to make the expected logging level visible.

oakbani · 2019-01-02T13:58:57Z

optimizely/helpers/audience.py

      audience.conditionStructure,
      lambda index: evaluate_custom_attr(audienceId, index)
    )

+    result_log = str(result) if result is not None else 'UNKNOWN'
+    logger.debug(logs.AUDIENCE_EVALUATION_RESULT.format(audienceId, result_log))


doc suggests that this should be info. I have made it debug to avoid logs being too verbose.
At info level we should be interested in the overall result, which we are already logging outside on line#87

…python-sdk into oakbani/logging-for-audience

nchilada

Thanks for doing this and sorry for the late review!

nchilada · 2019-02-20T00:33:13Z

optimizely/helpers/audience.py

  if audience_conditions is None or audience_conditions == []:
+    logger.info(logs.NO_AUDIENCE_ATTACHED.format(


Interesting idea to specifically mention the "no audiences" case. But to reduce the number of types of log messages, and to increase consistency with other SDKs, can we find a way to rely on the EVALUATING_AUDIENCES and AUDIENCE_EVALUATION_RESULT_COMBINED messages instead?

nchilada · 2019-02-20T00:38:19Z

optimizely/helpers/enums.py

+class AudienceEvaluationLogs(object):
+  AUDIENCE_EVALUATION_RESULT = 'Audience "{}" evaluated to {}.'
+  AUDIENCE_EVALUATION_RESULT_COMBINED = 'Audiences for experiment "{}" collectively evaluated to {}.'
+  EVALUATING_AUDIENCES = 'Evaluating audiences for experiment "{}": "{}".'


To match the changes we made in optimizely/javascript-sdk#210

Suggested change

EVALUATING_AUDIENCES = 'Evaluating audiences for experiment "{}": "{}".'

EVALUATING_AUDIENCES_COMBINED = 'Evaluating audiences for experiment "{}": {}.'

nchilada · 2019-02-20T00:39:27Z

optimizely/helpers/enums.py

+  AUDIENCE_EVALUATION_RESULT = 'Audience "{}" evaluated to {}.'
+  AUDIENCE_EVALUATION_RESULT_COMBINED = 'Audiences for experiment "{}" collectively evaluated to {}.'
+  EVALUATING_AUDIENCES = 'Evaluating audiences for experiment "{}": "{}".'
+  EVALUATING_AUDIENCE_WITH_CONDITIONS = 'Starting to evaluate audience "{}" with conditions: "{}".'


To match the changes we made in optimizely/javascript-sdk#210

Suggested change

EVALUATING_AUDIENCE_WITH_CONDITIONS = 'Starting to evaluate audience "{}" with conditions: "{}".'

EVALUATING_AUDIENCE = 'Evaluating audiences for experiment "{}": {}.'

renamed the key. The existing message is same as in JS SDK https://github.com/optimizely/javascript-sdk/pull/210/files#diff-79c0858a5dc2611f6570afc1265258daR127

nchilada · 2019-02-20T02:04:01Z

optimizely/helpers/audience.py

@@ -49,14 +63,28 @@ def evaluate_audience(audienceId):
    if audience is None:
      return None

-    return condition_tree_evaluator.evaluate(
+    logger.debug(logs.EVALUATING_AUDIENCE_WITH_CONDITIONS.format(audienceId, audience.conditions))


Suggested change

logger.debug(logs.EVALUATING_AUDIENCE_WITH_CONDITIONS.format(audienceId, audience.conditions))

logger.debug(logs.EVALUATING_AUDIENCE_WITH_CONDITIONS.format(audienceId, json.dumps(audience.conditions)))

audience.conditions are already JSON string encoded. https://github.com/optimizely/python-sdk/blob/master/optimizely/project_config.py#L73

Ah, thanks!

nchilada · 2019-02-20T02:06:08Z

optimizely/helpers/audience.py

      audience.conditionStructure,
      lambda index: evaluate_custom_attr(audienceId, index)
    )

+    result_str = str(result) if result is not None else 'UNKNOWN'


Suggested change

result_str = str(result) if result is not None else 'UNKNOWN'

result_str = str(result).upper() if result is not None else 'UNKNOWN'

nchilada · 2019-02-22T18:16:32Z

optimizely/helpers/condition.py

       not validator.are_values_same_type(condition_value, user_value):
-        return None
+      self.logger.debug(logs.UNEXPECTED_TYPE.format(


Suggested change

self.logger.debug(logs.UNEXPECTED_TYPE.format(

self.logger.warning(logs.UNEXPECTED_TYPE.format(

nchilada · 2019-02-22T18:18:22Z

optimizely/helpers/condition.py


-    if not validator.is_finite_number(condition_value) or not validator.is_finite_number(user_value):
+    if not validator.is_finite_number(user_value):
+      self.logger.debug(logs.UNEXPECTED_TYPE.format(


Suggested change

self.logger.debug(logs.UNEXPECTED_TYPE.format(

self.logger.warning(logs.UNEXPECTED_TYPE.format(

nchilada · 2019-02-22T18:18:53Z

optimizely/helpers/condition.py


-    if not validator.is_finite_number(condition_value) or not validator.is_finite_number(user_value):
+    if not validator.is_finite_number(user_value):
+      self.logger.debug(logs.UNEXPECTED_TYPE.format(


Suggested change

self.logger.debug(logs.UNEXPECTED_TYPE.format(

self.logger.warning(logs.UNEXPECTED_TYPE.format(

nchilada · 2019-02-22T18:19:03Z

optimizely/helpers/condition.py

+      return None
+
+    if not isinstance(user_value, string_types):
+      self.logger.debug(logs.UNEXPECTED_TYPE.format(


Suggested change

self.logger.debug(logs.UNEXPECTED_TYPE.format(

self.logger.warning(logs.UNEXPECTED_TYPE.format(

nchilada · 2019-02-22T18:19:58Z

optimizely/helpers/condition.py

+        return None
+
+      if self.attributes.get(attribute_key) is None:
+        self.logger.warning(logs.NULL_ATTRIBUTE_VALUE.format(self._get_condition_log(index), attribute_key))


Suggested change

self.logger.warning(logs.NULL_ATTRIBUTE_VALUE.format(self._get_condition_log(index), attribute_key))

self.logger.debug(logs.NULL_ATTRIBUTE_VALUE.format(self._get_condition_log(index), attribute_key))

oakbani · 2019-02-25T15:50:21Z

@nchilada Feedback addressed. The build is failing only for 3.4 due to some unrelated issue.

…ging-for-audience

nchilada

The code and tests are looking really good! @aliabbasrizvi this will be ready for final review and merging after the next round of updates.

nchilada · 2019-02-26T22:47:18Z

optimizely/helpers/condition.py

-      return None
+    if not self.is_value_type_valid_for_exact_conditions(condition_value) or \
+        self.is_value_a_number(condition_value) and \
+            not validator.is_finite_number(condition_value):


Can we use parens to explicitly group the latter two conditions?

(self.is_value_a_number(condition_value) and not validator.is_finite_number(condition_value):

nchilada · 2019-02-26T22:48:22Z

optimizely/helpers/condition.py

+              self.logger.warning(logs.UNKNOWN_CONDITION_VALUE.format(
+                self._get_condition_json(index)
+              ))
+              return None


Nit: it would be more conventional to indent these two statements by only 2 spaces.

nchilada · 2019-02-26T22:55:33Z

optimizely/helpers/enums.py

@@ -17,21 +17,20 @@
 class AudienceEvaluationLogs(object):
  AUDIENCE_EVALUATION_RESULT = 'Audience "{}" evaluated to {}.'
  AUDIENCE_EVALUATION_RESULT_COMBINED = 'Audiences for experiment "{}" collectively evaluated to {}.'
-  EVALUATING_AUDIENCES = 'Evaluating audiences for experiment "{}": "{}".'
-  EVALUATING_AUDIENCE_WITH_CONDITIONS = 'Starting to evaluate audience "{}" with conditions: "{}".'
+  EVALUATING_AUDIENCE = 'Starting to evaluate audience "{}" with conditions: "{}".'


Can we actually remove the surrounding quotation marks? That's what we ended up going with in other SDKs although we included quotes in the original design spec. Sorry!

Suggested change

EVALUATING_AUDIENCE = 'Starting to evaluate audience "{}" with conditions: "{}".'

EVALUATING_AUDIENCE = 'Starting to evaluate audience "{}" with conditions: {}.'

nchilada · 2019-02-26T23:13:55Z

tests/helpers_tests/test_audience.py

+    experiment.audienceIds = []
+    experiment.audienceConditions = []
+
+    with mock.patch('optimizely.logger.reset_logger', return_value=self.mock_client_logger):


Nit: does optimizely.logger.reset_logger actually need to return self.mock_client_logger given that we are passing self.mock_client_logger directly to the function we're testing, on the line below?

Same question elsewhere in the new tests.

nchilada · 2019-02-26T23:25:17Z

tests/helpers_tests/test_audience.py

+
+    self.mock_client_logger.assert_has_calls([
+      mock.call.debug('Evaluating audiences for experiment "test_experiment": ["11154", "11159"].'),
+      mock.call.debug('Starting to evaluate audience "11154" with conditions: "' + audience_11154.conditions + '".'),


We'll need to change this to

Suggested change

mock.call.debug('Starting to evaluate audience "11154" with conditions: "' + audience_11154.conditions + '".'),

mock.call.debug('Starting to evaluate audience "11154" with conditions: ' + audience_11154.conditions + '.'),

per the suggestion that I've made in enums.py. Or even better, IMO:

Suggested change

mock.call.debug('Starting to evaluate audience "11154" with conditions: "' + audience_11154.conditions + '".'),

mock.call.debug('Starting to evaluate audience "11154" with conditions: ["and", ["or", ["or", '

'{"name": "test_attribute", "type": "custom_attribute", "value": "test_value"}]]].'),

(Same thing below)

nchilada · 2019-02-26T23:40:13Z

tests/helpers_tests/test_condition.py

+    mock_log.assert_called_once_with((
+      'Audience condition "{}" uses an unknown match '
+      'type. You may need to upgrade to a newer release of the Optimizely SDK.')
+        .format(json.dumps(expected_condition_log)))


I'd still prefer to avoid using .format in our assertions since it's an ugly mirror, but it does help that we're only using it for the conditions now and not for other template variables in our log messages. I guess this is okay.

Yeah, for consistent unit tests we do need to use format in cases where representation varies across different python versions. Same for variable types.

nchilada · 2019-02-26T23:45:40Z

tests/helpers_tests/test_condition.py

+
+    self.assertStrictFalse(evaluator.evaluate(0))
+
+    self.mock_client_logger.debug.assert_not_called()


Can we also confirm that info and warning weren't called?

nchilada · 2019-02-26T23:46:06Z

tests/helpers_tests/test_condition.py

+
+    self.assertStrictFalse(evaluator.evaluate(0))
+
+    self.mock_client_logger.debug.assert_not_called()


Can we also confirm that info and warning weren't called?

nchilada · 2019-02-26T23:51:11Z

tests/helpers_tests/test_condition.py

+    mock_log = getattr(self.mock_client_logger, log_level)
+    mock_log.assert_called_once_with((
+      'Audience condition "{}" evaluated to UNKNOWN because a value of type "{}" was passed for '
+      'user attribute "favorite_constellation".').format(json.dumps(expected_condition_log), type({})))


It'd be really nice to inline the observed type into our assertion string. Both here and below. (As long as it works for both Python 2 and Python 3... might be tricky if we want to test the gt and lt match types with string-valued user attributes.)

We get different outputs in python 2 and 3 so can't hardcode type in string.

AssertionError: Expected call: warning('Audience condition "{"name": "meters_travelled", "value": 48, "type": "custom_attribute", "match": "gt"}" evaluated to UNKNOWN because a value of type "<type 'str'>" was passed for user attribute "meters_travelled".')
Actual call: warning('Audience condition "{"name": "meters_travelled", "value": 48, "type": "custom_attribute", "match": "gt"}" evaluated to UNKNOWN because a value of type "<class 'str'>" was passed for user attribute "meters_travelled".')

aliabbasrizvi · 2019-02-27T07:00:51Z

Thanks @nchilada . I am doing a review as well.

aliabbasrizvi · 2019-02-27T06:16:30Z

.travis.yml

@@ -25,7 +25,7 @@ jobs:
    - stage: 'Linting'
      language: python
      python: "2.7"
-      install: "pip install flake8"
+      install: "pip install flake8==3.6.0"


Can you put a note here why this is at 3.6.0. It will be useful for anyone else working on this file.

aliabbasrizvi · 2019-02-27T06:18:08Z

optimizely/helpers/audience.py

 from . import condition as condition_helper
 from . import condition_tree_evaluator
+from .enums import AudienceEvaluationLogs as logs


nit. ... as audience_logs

aliabbasrizvi · 2019-02-27T06:40:06Z

optimizely/helpers/audience.py

+
+  logger.debug(logs.EVALUATING_AUDIENCES_COMBINED.format(
+    experiment.key,
+    json.dumps(audience_conditions)


The second argument here I feel is unnecessary as one can figure out what the audience conditions are from the datafile and IDs anyway will not help a lot to me as a customer. I guess we have resorted to this message in other SDKs as well @nchilada ?

@aliabbasrizvi yeah, same message in other SDKs... Part of my reasoning was that log messages might be recorded and used for debugging after the fact, by which time the datafile may have changed. Currently it's very difficult (and it may always be unintuitive) for customers to look up the datafile that was contemporaneous with a particular log message.

aliabbasrizvi · 2019-02-27T07:10:23Z

optimizely/helpers/condition.py


 from six import string_types

 from . import validator
+from .enums import AudienceEvaluationLogs as logs


nit. ... as audience_logs

aliabbasrizvi · 2019-02-27T07:12:09Z

optimizely/helpers/condition.py

    """ Method to validate if the value is valid for exact match type evaluation.

    Args:
      value: Value to validate.

    Returns:
-      Boolean: True if value is a string type, or a boolean, or is finite. Otherwise False.
+      Boolean: True if value is a string type, or a boolean, or is a number. Otherwise False.


This sentence is too verbose. True if value is a string, boolean, or number.

nchilada

Thanks for all the updates and explanations! Looks great. 🙂

oakbani added 3 commits January 2, 2019 10:35

first pass

5f6832f

feat(Audience Evaluation): Add logging

e6bc6ee

🖊️ finalize logging

691c439

oakbani requested review from nchilada and msohailhussain January 2, 2019 13:48

oakbani commented Jan 2, 2019

View reviewed changes

Merge branch 'master' into oakbani/logging-for-audience

6b11de1

oakbani added the wip Work in progress label Jan 9, 2019

oakbani added 2 commits January 9, 2019 19:07

update comparison op

c946c5d

Merge branch 'oakbani/logging-for-audience' of github.com:optimizely/…

e65bd2e

…python-sdk into oakbani/logging-for-audience

oakbani removed the wip Work in progress label Jan 9, 2019

oakbani requested a review from a team January 9, 2019 14:15

oakbani and others added 5 commits January 10, 2019 18:29

Null unexpected type

0d6e733

Merge branch 'master' into oakbani/logging-for-audience

701ee8c

Updated according to doc

1196b89

refact: new recommendations.

0c19638

refact: Adds infinite value log message

9dcc6ab

nchilada suggested changes Feb 22, 2019

View reviewed changes

oakbani added 2 commits February 25, 2019 19:08

Address comments

4f13300

fix for other python versions

76e5898

another discrepancy across python versions

b24fb83

oakbani added 4 commits February 26, 2019 12:00

Add newer testcases

11e8d8a

Merge remote-tracking branch 'remotes/origin/master' into oakbani/log…

ba29134

…ging-for-audience

lint for flake8

c3aa3fa

use flake8 version in requirement.txt

95be1d2

nchilada suggested changes Feb 26, 2019

View reviewed changes

aliabbasrizvi reviewed Feb 27, 2019

View reviewed changes

address further feedback

3d0bfee

nchilada approved these changes Feb 27, 2019

View reviewed changes

nchilada merged commit fafad4c into master Feb 28, 2019

nchilada deleted the oakbani/logging-for-audience branch February 28, 2019 19:44

		if audience_conditions is None or audience_conditions == []:
		logger.info(logs.NO_AUDIENCE_ATTACHED.format(

	EVALUATING_AUDIENCES = 'Evaluating audiences for experiment "{}": "{}".'
	EVALUATING_AUDIENCES_COMBINED = 'Evaluating audiences for experiment "{}": {}.'

	EVALUATING_AUDIENCE_WITH_CONDITIONS = 'Starting to evaluate audience "{}" with conditions: "{}".'
	EVALUATING_AUDIENCE = 'Evaluating audiences for experiment "{}": {}.'

	logger.debug(logs.EVALUATING_AUDIENCE_WITH_CONDITIONS.format(audienceId, audience.conditions))
	logger.debug(logs.EVALUATING_AUDIENCE_WITH_CONDITIONS.format(audienceId, json.dumps(audience.conditions)))

	result_str = str(result) if result is not None else 'UNKNOWN'
	result_str = str(result).upper() if result is not None else 'UNKNOWN'

	self.logger.debug(logs.UNEXPECTED_TYPE.format(
	self.logger.warning(logs.UNEXPECTED_TYPE.format(

	self.logger.warning(logs.NULL_ATTRIBUTE_VALUE.format(self._get_condition_log(index), attribute_key))
	self.logger.debug(logs.NULL_ATTRIBUTE_VALUE.format(self._get_condition_log(index), attribute_key))

	EVALUATING_AUDIENCE = 'Starting to evaluate audience "{}" with conditions: "{}".'
	EVALUATING_AUDIENCE = 'Starting to evaluate audience "{}" with conditions: {}.'

	mock.call.debug('Starting to evaluate audience "11154" with conditions: "' + audience_11154.conditions + '".'),
	mock.call.debug('Starting to evaluate audience "11154" with conditions: ' + audience_11154.conditions + '.'),

	mock.call.debug('Starting to evaluate audience "11154" with conditions: "' + audience_11154.conditions + '".'),
	mock.call.debug('Starting to evaluate audience "11154" with conditions: ["and", ["or", ["or", '
	'{"name": "test_attribute", "type": "custom_attribute", "value": "test_value"}]]].'),


		self.assertStrictFalse(evaluator.evaluate(0))

		self.mock_client_logger.debug.assert_not_called()

feat(Audience Evaluation): Audience Logging #156

feat(Audience Evaluation): Audience Logging #156

Conversation

oakbani commented Jan 2, 2019 • edited by nchilada Loading

Summary

Test plan

Issues

coveralls commented Jan 2, 2019

coveralls commented Jan 2, 2019

coveralls commented Jan 2, 2019

coveralls commented Jan 2, 2019

coveralls commented Jan 2, 2019

coveralls commented Jan 2, 2019 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

nchilada left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

oakbani commented Feb 25, 2019

nchilada left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

aliabbasrizvi commented Feb 27, 2019

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

nchilada left a comment

Choose a reason for hiding this comment

oakbani commented Jan 2, 2019 •

edited by nchilada

Loading

coveralls commented Jan 2, 2019 •

edited

Loading