(U2C #12) improve error handling/logging in evaluations (#113)

eli-darkly · web-flow · commit 0053143a1bbf · 2022-10-20T11:01:02.000-07:00
diff --git a/Makefile b/Makefile
@@ -16,9 +16,7 @@ TEMP_TEST_OUTPUT=/tmp/sse-contract-test-service.log
 #   arrays work, there's no way to disallow an array index lookup without breaking object property
 #   lookups for properties that are numeric strings.
 # - "evaluation/parameterized/prerequisites": Can't pass yet because prerequisite cycle detection is not implemented.
-# - "evaluation/parameterized/segment match": Haven't yet implemented context kinds in segments.
 # - "evaluation/parameterized/segment recursion": Haven't yet implemented segment recursion.
-# - various other "evaluation" subtests: These tests require context kind support.
 # - "events": These test suites will be unavailable until more of the U2C implementation is done.
 TEST_HARNESS_PARAMS := $(TEST_HARNESS_PARAMS) \
 	-skip 'evaluation/bucketing/secondary' \
diff --git a/src/LaunchDarkly/Impl/Evaluation/Evaluator.php b/src/LaunchDarkly/Impl/Evaluation/Evaluator.php
@@ -10,7 +10,9 @@
 use LaunchDarkly\Impl\Model\Rule;
 use LaunchDarkly\Impl\Model\Segment;
 use LaunchDarkly\Impl\Model\SegmentRule;
+use LaunchDarkly\Impl\Util;
 use LaunchDarkly\LDContext;
+use Psr\Log\LoggerInterface;
 
 /**
  * Encapsulates the feature flag evaluation logic. The Evaluator has no direct access to the
@@ -23,10 +25,12 @@
 class Evaluator
 {
     private FeatureRequester $_featureRequester;
+    private LoggerInterface $_logger;
 
-    public function __construct(FeatureRequester $featureRequester)
+    public function __construct(FeatureRequester $featureRequester, ?LoggerInterface $logger = null)
     {
         $this->_featureRequester = $featureRequester;
+        $this->_logger = $logger ?: Util::makeNullLogger();
     }
 
     /**
@@ -54,40 +58,52 @@ private function evaluateInternal(
         LDContext $context,
         ?callable $prereqEvalSink
     ): EvalResult {
-        if (!$flag->isOn()) {
-            return EvaluatorHelpers::getOffResult($flag, EvaluationReason::off());
-        }
+        try {
+            // The reason there's an extra try block here is that if something fails during evaluation of the
+            // prerequisites, we don't want that to short-circuit evaluation of the base flag in the way that
+            // an error normally would, where the whole evaluation would return an error result with a default
+            // value. Instead we want the base flag to return its off variation, as it always does if any
+            // prerequisites have failed.
+            if (!$flag->isOn()) {
+                return EvaluatorHelpers::getOffResult($flag, EvaluationReason::off());
+            }
 
-        $prereqFailureReason = $this->checkPrerequisites($flag, $context, $prereqEvalSink);
-        if ($prereqFailureReason !== null) {
-            return EvaluatorHelpers::getOffResult($flag, $prereqFailureReason);
-        }
+            $prereqFailureReason = $this->checkPrerequisites($flag, $context, $prereqEvalSink);
+            if ($prereqFailureReason !== null) {
+                return EvaluatorHelpers::getOffResult($flag, $prereqFailureReason);
+            }
 
-        // Check to see if targets match
-        $targetResult = $this->checkTargets($flag, $context);
-        if ($targetResult) {
-            return $targetResult;
-        }
+            // Check to see if targets match
+            $targetResult = $this->checkTargets($flag, $context);
+            if ($targetResult) {
+                return $targetResult;
+            }
 
-        // Now walk through the rules and see if any match
-        foreach ($flag->getRules() as $i => $rule) {
-            if ($this->ruleMatchesContext($rule, $context)) {
-                return EvaluatorHelpers::getResultForVariationOrRollout(
-                    $flag,
-                    $rule,
-                    $rule->isTrackEvents(),
-                    $context,
-                    EvaluationReason::ruleMatch($i, $rule->getId())
-                );
+            // Now walk through the rules and see if any match
+            foreach ($flag->getRules() as $i => $rule) {
+                if ($this->ruleMatchesContext($rule, $context)) {
+                    return EvaluatorHelpers::getResultForVariationOrRollout(
+                        $flag,
+                        $rule,
+                        $rule->isTrackEvents(),
+                        $context,
+                        EvaluationReason::ruleMatch($i, $rule->getId())
+                    );
+                }
             }
+            return EvaluatorHelpers::getResultForVariationOrRollout(
+                $flag,
+                $flag->getFallthrough(),
+                $flag->isTrackEventsFallthrough(),
+                $context,
+                EvaluationReason::fallthrough()
+            );
+        } catch (EvaluationException $e) {
+            return new EvalResult(new EvaluationDetail(null, null, EvaluationReason::error($e->getErrorKind())));
+        } catch (\Throwable $e) {
+            Util::logExceptionAtErrorLevel($this->_logger, $e, 'Unexpected error when evaluating flag ' . $flag->getKey());
+            return new EvalResult(new EvaluationDetail(null, null, EvaluationReason::error(EvaluationReason::EXCEPTION_ERROR)));
         }
-        return EvaluatorHelpers::getResultForVariationOrRollout(
-            $flag,
-            $flag->getFallthrough(),
-            $flag->isTrackEventsFallthrough(),
-            $context,
-            EvaluationReason::fallthrough()
-        );
     }
 
     private function checkPrerequisites(
@@ -99,9 +115,11 @@ private function checkPrerequisites(
             $prereqOk = true;
             try {
                 $prereqFeatureFlag = $this->_featureRequester->getFeature($prereq->getKey());
-                if ($prereqFeatureFlag == null) {
+                if ($prereqFeatureFlag === null) {
                     $prereqOk = false;
                 } else {
+                    // Note that if the prerequisite flag is off, we don't consider it a match no matter what its
+                    // off variation was. But we still need to evaluate it in order to generate an event.
                     $prereqEvalResult = $this->evaluateInternal($prereqFeatureFlag, $context, $prereqEvalSink);
                     $variation = $prereq->getVariation();
                     if (!$prereqFeatureFlag->isOn() || $prereqEvalResult->getDetail()->getVariationIndex() !== $variation) {
@@ -111,7 +129,12 @@ private function checkPrerequisites(
                         $prereqEvalSink(new PrerequisiteEvaluationRecord($prereqFeatureFlag, $flag, $prereqEvalResult));
                     }
                 }
-            } catch (\Exception $e) {
+            } catch (\Throwable $e) {
+                Util::logExceptionAtErrorLevel(
+                    $this->_logger,
+                    $e,
+                    'Unexpected error when evaluating prerequisite flag ' . $prereq->getKey()
+                );
                 $prereqOk = false;
             }
             if (!$prereqOk) {
diff --git a/src/LaunchDarkly/Impl/Util.php b/src/LaunchDarkly/Impl/Util.php
@@ -6,6 +6,9 @@
 
 use DateTime;
 use DateTimeZone;
+use Monolog\Handler\NullHandler;
+use Monolog\Logger;
+use Psr\Log\LoggerInterface;
 
 /**
  * Internal class containing helper methods.
@@ -50,4 +53,15 @@ public static function httpErrorMessage(int $status, string $context, string $re
             . ' for ' . $context . ' - '
             . (Util::isHttpErrorRecoverable($status) ? $retryMessage : 'giving up permanently');
     }
+
+    public static function logExceptionAtErrorLevel(LoggerInterface $logger, \Throwable $e, string $message): void
+    {
+        $logger->error($message . ': ' . $e->getMessage());
+        $logger->debug("$e");
+    }
+
+    public static function makeNullLogger(): LoggerInterface
+    {
+        return new Logger('', [new NullHandler()]);
+    }
 }
diff --git a/src/LaunchDarkly/LDClient.php b/src/LaunchDarkly/LDClient.php
@@ -12,6 +12,7 @@
 use LaunchDarkly\Impl\Model\FeatureFlag;
 use LaunchDarkly\Impl\PreloadedFeatureRequester;
 use LaunchDarkly\Impl\UnrecoverableHTTPStatusException;
+use LaunchDarkly\Impl\Util;
 use LaunchDarkly\Integrations\Guzzle;
 use Monolog\Handler\ErrorLogHandler;
 use Monolog\Logger;
@@ -138,7 +139,7 @@ public function __construct(string $sdkKey, array $options = [])
 
         $this->_featureRequester = $this->getFeatureRequester($sdkKey, $options);
 
-        $this->_evaluator = new Evaluator($this->_featureRequester);
+        $this->_evaluator = new Evaluator($this->_featureRequester, $this->_logger);
     }
 
     /**
@@ -279,13 +280,9 @@ function (PrerequisiteEvaluationRecord $pe) {
             $sendEvent($detail, $flag);
             return $detail;
         } catch (\Exception $e) {
-            $this->_logger->error("Caught $e");
+            Util::logExceptionAtErrorLevel($this->_logger, $e, "Unexpected error evaluating flag $key");
             $result = $errorResult(EvaluationReason::EXCEPTION_ERROR);
-            try {
-                $sendEvent($result, null);
-            } catch (\Exception $e) {
-                $this->_logger->error("Caught $e");
-            }
+            $sendEvent($result, null);
             return $result;
         }
     }
diff --git a/test-service/TestService.php b/test-service/TestService.php
@@ -26,7 +26,7 @@ public function __construct(TestDataStore $store, Logger $logger)
         });
 
         $this->_app->route('POST /', function () {
-            $params = $this->_app->request()->data;
+            $params = self::parseRequestJson($this->_app->request()->getBody());
             $id = $this->createClient($params);
             header("Location:/clients/$id");
         });
@@ -37,7 +37,8 @@ public function __construct(TestDataStore $store, Logger $logger)
                 http_response_code(404);
                 return;
             }
-            $resp = $c->doCommand($this->_app->request()->data);
+            $params = self::parseRequestJson($this->_app->request()->getBody());
+            $resp = $c->doCommand($params);
             if ($resp === false) {
                 http_response_code(400);
             } elseif (is_array($resp)) {
@@ -102,4 +103,39 @@ private function getClient(string $id): ?SdkClientEntity
         }
         return new SdkClientEntity($params);
     }
+
+    // The following methods for normalizing parsed JSON are a workaround for PHP's inability to distinguish
+    // between an empty JSON array [] and an empty JSON object {} if you parse JSON into associative arrays.
+    // In order for some contract tests to work which involve empty object values, we need to be able to
+    // make such a distinction. But, we don't want to parse all of the JSON parameters as objects, because
+    // associative arrays are much more convenient for most of our logic. The solution is to parse everything
+    // as an object first, then convert every object to an array UNLESS it is an empty object.
+
+    private static function parseRequestJson(string $json): array
+    {
+        return self::normalizeParsedData(json_decode($json));
+    }
+
+    private static function normalizeParsedData(mixed $value): mixed
+    {
+        if (is_array($value)) {
+            $ret = [];
+            foreach ($value as $element) {
+                $ret[] = self::normalizeParsedData($element);
+            }
+            return $ret;
+        }
+        if (!is_object($value)) {
+            return $value;
+        }
+        $props = get_object_vars($value);
+        if (count($props) === 0) {
+            return $value;
+        }
+        $ret = [];
+        foreach ($props as $k => $v) {
+            $ret[$k] = self::normalizeParsedData($v);
+        }
+        return $ret;
+    }
 }
diff --git a/tests/Impl/Evaluation/EvaluatorFlagTest.php b/tests/Impl/Evaluation/EvaluatorFlagTest.php
@@ -95,22 +95,22 @@ public function testFlagReturnsOffVariationIfPrerequisiteIsNotFound()
 
     public function testFlagReturnsOffVariationAndEventIfPrerequisiteIsOff()
     {
-        $flag0 = ModelBuilders::flagBuilder('feature0')->variations('fall', 'off', 'on')
-            ->on(true)->offVariation(1)->fallthroughVariation(0)
-            ->prerequisite('feature1', 1)
-            ->build();
         $flag1 = ModelBuilders::flagBuilder('feature1')->variations('nogo', 'go')
             ->on(false)->offVariation(1)->fallthroughVariation(0)
             // note that even though it returns the desired variation, it is still off and therefore not a match
             ->build();
+        $flag0 = ModelBuilders::flagBuilder('feature0')->variations('fall', 'off', 'on')
+            ->on(true)->offVariation(1)->fallthroughVariation(0)
+            ->prerequisite($flag1->getKey(), 1)
+            ->build();
 
         $requester = new MockFeatureRequester();
         $requester->addFlag($flag1);
         $evaluator = new Evaluator($requester);
         $recorder = EvaluatorTestUtil::prerequisiteRecorder();
 
         $result = $evaluator->evaluate($flag0, LDContext::create('user'), $recorder->record());
-        $detail = new EvaluationDetail('off', 1, EvaluationReason::prerequisiteFailed('feature1'));
+        $detail = new EvaluationDetail('off', 1, EvaluationReason::prerequisiteFailed($flag1->getKey()));
         self::assertEquals($detail, $result->getDetail());
 
         self::assertEquals(1, count($recorder->evals));
@@ -122,12 +122,12 @@ public function testFlagReturnsOffVariationAndEventIfPrerequisiteIsOff()
 
     public function testFlagReturnsOffVariationAndEventIfPrerequisiteIsNotMet()
     {
-        $flag0 = ModelBuilders::flagBuilder('feature0')->variations('fall', 'off', 'on')
+        $flag1 = ModelBuilders::flagBuilder('feature1')->variations('nogo', 'go')
             ->on(true)->offVariation(1)->fallthroughVariation(0)
-            ->prerequisite('feature1', 1)
             ->build();
-        $flag1 = ModelBuilders::flagBuilder('feature1')->variations('nogo', 'go')
+        $flag0 = ModelBuilders::flagBuilder('feature0')->variations('fall', 'off', 'on')
             ->on(true)->offVariation(1)->fallthroughVariation(0)
+            ->prerequisite($flag1->getKey(), 1)
             ->build();
 
         $requester = new MockFeatureRequester();
@@ -136,7 +136,7 @@ public function testFlagReturnsOffVariationAndEventIfPrerequisiteIsNotMet()
         $recorder = EvaluatorTestUtil::prerequisiteRecorder();
 
         $result = $evaluator->evaluate($flag0, LDContext::create('user'), $recorder->record());
-        $detail = new EvaluationDetail('off', 1, EvaluationReason::prerequisiteFailed('feature1'));
+        $detail = new EvaluationDetail('off', 1, EvaluationReason::prerequisiteFailed($flag1->getKey()));
         self::assertEquals($detail, $result->getDetail());
 
         self::assertEquals(1, count($recorder->evals));
@@ -148,13 +148,13 @@ public function testFlagReturnsOffVariationAndEventIfPrerequisiteIsNotMet()
 
     public function testFlagReturnsFallthroughVariationAndEventIfPrerequisiteIsMetAndThereAreNoRules()
     {
-        $flag0 = ModelBuilders::flagBuilder('feature0')->variations('fall', 'off', 'on')
-            ->on(true)->fallthroughVariation(0)
-            ->prerequisite('feature1', 1)
-            ->build();
         $flag1 = ModelBuilders::flagBuilder('feature1')->variations('nogo', 'go')
             ->on(true)->offVariation(1)->fallthroughVariation(1)
             ->build();
+        $flag0 = ModelBuilders::flagBuilder('feature0')->variations('fall', 'off', 'on')
+            ->on(true)->fallthroughVariation(0)
+            ->prerequisite($flag1->getKey(), 1)
+            ->build();
 
         $requester = new MockFeatureRequester();
         $requester->addFlag($flag1);
