feat: throw condition exception on TestNode exception #471

k13gomez · 2021-12-20T22:01:59Z

ensure we throw a more detailed condition exception when an exception is encountered during the evaluation of a TestNode expression

Closes #472

k13gomez · 2021-12-20T22:03:14Z

I need to add some test cases, but working on this feature so that we get more detailed exceptions (at a minimum knowing the rule where the exception is thrown)

EthanEChristian · 2021-12-20T22:14:22Z

@k13gomez,

Would it be possible to log an issue for this feature, and provide a sample of the current exception and an ideal message?

edit: mainly for tracking purposes

k13gomez · 2021-12-21T16:08:31Z

@EthanEChristian I created issue #472 with some details, also I will be adding unit tests for clarity.

k13gomez · 2021-12-21T19:51:21Z

New stacktrace printout:

clojure.lang.ExceptionInfo: Condition exception raised.
when processing fact
  #clara.rules.testfacts.WindSpeed{:windspeed 10, :location "MCI"}
  #clara.rules.testfacts.Temperature{:temperature nil, :location "MCI"}
with bindings
  {:?w 10, :?t nil}
Conditions:

1. [:test (> ?t ?w)]
   queries:
     my-test-query

 at clojure.core$ex_info.invoke (core.clj:4593)
    clara.rules.engine$throw_condition_exception.invoke (engine.cljc:507)
    clara.rules.engine$test_node_matches$fn__6131.invoke (engine.cljc:934)
    clara.rules.engine$test_node_matches.invoke (engine.cljc:931)
    clojure.core$partial$fn__4531.invoke (core.clj:2507)
    clojure.core$filter$fn__4580.invoke (core.clj:2690)
    clojure.lang.LazySeq.sval (LazySeq.java:40)
    clojure.lang.LazySeq.seq (LazySeq.java:49)
    clojure.lang.RT.seq (RT.java:507)
    clojure.core/seq (core.clj:137)
    clara.rules.engine$propagate_items_to_nodes.invoke (engine.cljc:164)
    clara.rules.engine.LocalTransport.send_tokens (engine.cljc:179)
    clara.rules.engine.TestNode.left_activate (engine.cljc:953)
    clara.rules.engine$eval4927$fn__4971$G__4913__4978.invoke (engine.cljc:99)
    clara.rules.engine$eval4927$fn__4971$G__4912__4986.invoke (engine.cljc:99)
    clara.rules.engine$propagate_items_to_nodes.invoke (engine.cljc:165)
    clara.rules.engine.LocalTransport.send_tokens (engine.cljc:179)
    clara.rules.engine.HashJoinNode.right_activate (engine.cljc:651)
    clara.rules.engine$eval5008$fn__5009$G__4998__5016.invoke (engine.cljc:107)
    clara.rules.engine$eval5008$fn__5009$G__4997__5024.invoke (engine.cljc:107)
    clara.rules.engine$propagate_items_to_nodes.invoke (engine.cljc:165)
    clara.rules.engine.LocalTransport.send_elements (engine.cljc:176)
    clara.rules.engine.AlphaNode.alpha_activate (engine.cljc:540)
    clara.rules.engine.LocalSession/fn (engine.cljc:1932)
    clara.rules.engine.LocalSession.fire_rules (engine.cljc:1925)
    clara.rules$fire_rules.invoke (rules.cljc:44)
    clara.test_rules$eval16115$fn__16116.invoke (form-init3212989977979054669.clj:2376)
    clara.test_rules$eval16115.invoke (form-init3212989977979054669.clj:2373)
    clojure.lang.Compiler.eval (Compiler.java:6782)
    clojure.lang.Compiler.eval (Compiler.java:6745)
    clojure.core$eval.invoke (core.clj:3081)
    nrepl.middleware.interruptible_eval$evaluate$fn__744.invoke (interruptible_eval.clj:91)
    clojure.main$repl$read_eval_print__7099$fn__7102.invoke (main.clj:240)
    clojure.main$repl$read_eval_print__7099.invoke (main.clj:240)
    clojure.main$repl$fn__7108.invoke (main.clj:258)
    clojure.main$repl.doInvoke (main.clj:258)
    clojure.lang.RestFn.invoke (RestFn.java:1523)
    nrepl.middleware.interruptible_eval$evaluate.invoke (interruptible_eval.clj:84)
    nrepl.middleware.interruptible_eval$interruptible_eval$fn__770$fn__774.invoke (interruptible_eval.clj:155)
    clojure.lang.AFn.run (AFn.java:22)
    nrepl.middleware.session$session_exec$main_loop__867$fn__869.invoke (session.clj:190)
    nrepl.middleware.session$session_exec$main_loop__867.invoke (session.clj:189)
    clojure.lang.AFn.run (AFn.java:22)
    java.lang.Thread.run (Thread.java:748)
Caused by: java.lang.NullPointerException: null
 at clojure.lang.Numbers.ops (Numbers.java:1013)
    clojure.lang.Numbers.gt (Numbers.java:229)
    clara.test_rules$eval13532$TN_3_TE__13539.invoke (form-init3212989977979054669.clj:2368)
    clara.test_rules$eval13532$fn__13541.invoke (form-init3212989977979054669.clj:2368)
    clojure.lang.AFn.applyToHelper (AFn.java:154)
    ...

EthanEChristian · 2021-12-22T20:56:43Z

src/main/clojure/clara/rules/engine.cljc

+
+  IConditionNode
+  (get-condition-description [this]
+    (into [:test] (:constraints (meta test)))))


Might be interesting to have a test that confirms that this metadata is maintained across a serialization/deserialization.

I feel fairly confident that the metadata would survive as the entire form should be captured, but incase something changes in the future, a test to catch it would be good.

The test would likely need to be added somewhere in the durability test:
https://github.com/cerner/clara-rules/blob/main/src/test/clojure/clara/test_durability.clj

Sure, I will add that in as we also rely serialization heavily; I'm testing it live today on our backend.

@EthanEChristian I've added a test to ensure that the metadata is maintained across a serialization/deserialization, it worked as expected. I also tested this on a live system and worked as expected.

EthanEChristian · 2021-12-22T20:58:33Z

Overall, i think this makes sense and I am glad you were able to thread it into the pattern that we have for other node types.

k13gomez · 2021-12-23T01:54:42Z

If this looks good to merge can you approve? Ideally I'd like to get this in and cut a release.

mrrodriguez · 2021-12-23T04:44:17Z

src/main/clojure/clara/rules/compiler.clj

+    `(let [handler# (fn ~fn-name [~'?__token__]
+                      (let [~@assignments]
+                        (and ~@constraints)))]
+       (with-meta handler#


There may be a reason to be concerned here about the overhead of using with-meta to wrap the fn.

with-meta wraps the fn in a RestFn here https://github.com/clojure/clojure/blob/clojure-1.10.3/src/jvm/clojure/lang/AFunction.java#L29
which has the unfortunate consequence of making all calls to the wrapped fn go through variadic arg runtime unrolling via apply https://github.com/clojure/clojure/blob/clojure-1.10.3/src/jvm/clojure/lang/AFunction.java#L31

The constraint fn's themselves may be called in hot spots so this can be concerning.

Microbench mark example (ran it a bunch of times to stabilize the numbers):

(let [f (fn [x] (inc x)) mf (with-meta f {:my :meta})] (time (dotimes [_ 1e5] (f 2))) (time (dotimes [_ 1e5] (mf 2)))) ;;= "Elapsed time: 3.851125 msecs" ;;= "Elapsed time: 22.38039 msecs" ;;= nil

True, there’s a bit of an overhead, the alternative approach I was considering was creating a protocol for the test expression handler instead of using a Fn directly so that it could carry the additional metadata needed for introspection at runtime, or just simply capturing that data when compile-test is called. It will require refactoring more tests but I can make an alternative PR with that approach.

One possible way out of this sort of mess would be if this fn could just return this map instead and then
https://github.com/cerner/clara-rules/blob/014ed43ed2960d64db065a1fd108dce336aac960/src/main/clojure/clara/rules/compiler.clj#L1443
would use the :handler value directly.

However, I think then there may be an issue with the durability layer persisting this meta information via serde...

@mrrodriguez in my experience it gets persisted just fine because the durability layer persists the productions but removes the compiled portion, so it would recompile them whenever the session was reassembled.

mrrodriguez

I have some comments and concerns.

Also, I'm wondering if the PR title is correct. My understanding of this issue is that there is a desire to add better error reporting for :test nodes specifically correct?

mrrodriguez · 2021-12-23T04:45:47Z

src/main/clojure/clara/rules/engine.cljc

@@ -494,7 +494,9 @@
                               (str "with bindings\n  " bindings))
        message-header (string/join ["Condition exception raised.\n"
                                     "when processing fact\n"
-                                     (str "  " (pr-str fact) "\n")
+                                     (str "  " (->> (flatten [fact])


As a general principle I think it almost always is a red flag to need to use flatten. What is arbitrary and out of control about the structure here that makes this necessary?

If the problem is just that sometimes fact is not a fact, but rather a collection of facts, I think that should be handled explicitly to only unroll that top level.

Better yet, I think the name should just be changed to facts and all callers should pass a collection. If they only have 1 they can put that in a coll too.

Also is there any chance that this list of facts could be very large and cause a flood of output, eg. from accumulated coll values?

@mrrodriguez I updated the PR title and description, I ended up rewriting the initial PR and targeting just the TestNode which is where there was missing exception handling logic; now, regarding the list of facts, this is the same possibility of flood of output with all the other Condition Exceptions where bindings are listed, because it is possible for the bindings used in a TestNode to be a list of accumulated facts all the same. I am wondering if I should change it so that the condition exception raised by the TestNode does not actually list facts because it does not really bind to any fact but it is purely dependent on the bindings and that is all that should be needed along with the condition/query encountering the exception.

I agree that flatten shouldn't be used here. It's a blunt tool that makes it more difficult to understand the data structures being used and could hide logic errors, which is problematic with the complex data structures Clara passes around internally. :)

The need for this is coming from the :facts line in this code right though?

(throw-condition-exception {:cause e :node node :env env :fact (keys (into {} (:matches token))) :bindings (:bindings token)})

I don't think we need the :fact argument here though at all for TestNode as @k13gomez was considering above. Perhaps information on all previous facts in the rule network prior to reaching the error-throwing node, regardless of whether they were bound to variables, could be a useful addition in some use cases, but I don't think that's what we're currently doing for join nodes for example: https://github.com/cerner/clara-rules/blob/8107a5ab7fdb475e323c0bcb39084a83454deb1c/src/main/clojure/clara/rules/engine.cljc#L669
If we did want that I'd suggest representing that as something other than :fact but IMO is out of scope here.

I think it makes sense to remove the fact altogether for the :test node so I will be doing that.

mrrodriguez · 2021-12-23T04:48:47Z

src/main/clojure/clara/rules/engine.cljc

@@ -937,15 +950,19 @@
     memory
     listener
     children
-     (filter test tokens)))
+     (filter (partial test-node-matches node test {}) tokens)))


FYI: partial degrades performance possibly significantly beyond it's 4 arity case. So this is pushing it right up against the limit.

Good point, I'm going to remove the env argument since it doesn't really get used, I was just sticking to the existing pattern. Another possibility is to write this as an eager-for comprehension, so I'm going to give that a try.

mrrodriguez · 2021-12-23T04:52:12Z

src/test/clojure/clara/test_rules.clj

+      (is (= {:?w 10, :?t nil}
+             (-> e (ex-data) :bindings))))))
+
+(deftest test-local-scope-visible-in-test-filter


I'm confused by this test case's name since it seems to be checking that the :test node is throwing an exception due to the ?t value being nil right?

I'll give it a more descriptive name and actually add additional assertions since there's a couple more things I want to check on this exception.

mrrodriguez · 2021-12-23T04:52:38Z

src/test/clojure/clara/test_rules.clj

+                  (fire-rules)
+                  (query check-exception))
+              (is false "Scope binding test is expected to throw an exception.")
+              (catch Exception e e))]


Shouldn't there be some validation that the exception has the useful information that was added in this PR?

Yes, I'll add additional assertions to validate that.

Here are some similar tests in case you haven't seen them: https://github.com/cerner/clara-rules/blob/8107a5ab7fdb475e323c0bcb39084a83454deb1c/src/test/clojure/clara/test_rules.clj#L2020

mrrodriguez · 2021-12-23T04:54:43Z

src/main/clojure/clara/rules/compiler.clj

+    `(let [handler# (fn ~fn-name [~'?__token__]
+                      (let [~@assignments]
+                        (and ~@constraints)))]
+       (with-meta handler#


One possible way out of this sort of mess would be if this fn could just return this map instead and then
https://github.com/cerner/clara-rules/blob/014ed43ed2960d64db065a1fd108dce336aac960/src/main/clojure/clara/rules/compiler.clj#L1443
would use the :handler value directly.

However, I think then there may be an issue with the durability layer persisting this meta information via serde...

k13gomez · 2021-12-23T05:22:02Z

Thanks for all the feedback, I’ll work on this over the next few weeks, I think some of the questions and concerns should also lead to some new test cases.

WilliamParker · 2022-01-02T21:18:16Z

src/main/clojure/clara/rules/engine.cljc

@@ -494,7 +494,9 @@
                               (str "with bindings\n  " bindings))
        message-header (string/join ["Condition exception raised.\n"
                                     "when processing fact\n"
-                                     (str "  " (pr-str fact) "\n")
+                                     (str "  " (->> (flatten [fact])


I agree that flatten shouldn't be used here. It's a blunt tool that makes it more difficult to understand the data structures being used and could hide logic errors, which is problematic with the complex data structures Clara passes around internally. :)

The need for this is coming from the :facts line in this code right though?

(throw-condition-exception {:cause e :node node :env env :fact (keys (into {} (:matches token))) :bindings (:bindings token)})

I don't think we need the :fact argument here though at all for TestNode as @k13gomez was considering above. Perhaps information on all previous facts in the rule network prior to reaching the error-throwing node, regardless of whether they were bound to variables, could be a useful addition in some use cases, but I don't think that's what we're currently doing for join nodes for example: https://github.com/cerner/clara-rules/blob/8107a5ab7fdb475e323c0bcb39084a83454deb1c/src/main/clojure/clara/rules/engine.cljc#L669
If we did want that I'd suggest representing that as something other than :fact but IMO is out of scope here.

WilliamParker · 2022-01-03T14:29:11Z

src/test/clojure/clara/test_durability.clj

+      (is (= [[:test '(not-empty ?ts)]]
+             (map eng/get-condition-description (get-test-nodes s))
+             (map eng/get-condition-description (get-test-nodes restored1))
+             (map eng/get-condition-description (get-test-nodes restored2)))))))


I suggest directly validating that the restored TestNode still works. Something like the following perhaps:

Call fire-rules on the deserialized session and validate that there is no TemperatureHistory.

Insert a Temperature into the deserialized session, call fire-rules, and validate that there is a TemperatureHistory fact.

I see that there is https://github.com/cerner/clara-rules/blob/fb171cbe36ce766ebd20d625e87ee1dab9899161/src/test/clojure/clara/test_durability.clj#L236 but it looks like that is targeted at testing the memory SerDe rather than the handler.

I've improved this test it now fires and then re-fires the serialized session as described above.

WilliamParker · 2022-01-03T14:55:38Z

src/test/clojure/clara/test_rules.clj

+                  (fire-rules)
+                  (query check-exception))
+              (is false "Scope binding test is expected to throw an exception.")
+              (catch Exception e e))]


Here are some similar tests in case you haven't seen them: https://github.com/cerner/clara-rules/blob/8107a5ab7fdb475e323c0bcb39084a83454deb1c/src/test/clojure/clara/test_rules.clj#L2020

k13gomez · 2022-01-11T04:04:45Z

I've made several changes to address the PR feedback, please take a second look at the current state of this change

WilliamParker

I had a couple minor comments/thoughts but basically this looks good and I think it could be merged as is.

WilliamParker · 2022-01-17T00:36:54Z

src/main/clojure/clara/rules/engine.cljc

                               (str "with bindings\n  " bindings))
+        facts-description (if-not (contains? args :fact)


Minor: IMO this would perhaps be a bit easier to read as

(if (contains? args :fact) (str "when processing fact\n " (pr-str fact) "with no fact"))

in that avoiding the negation is one less step to follow. Not a big deal though and perhaps just a matter of personal taste.

good suggestion, makes sense, I think i will do that.

WilliamParker · 2022-01-17T00:51:48Z

src/test/clojure/clara/test_rules.clj

+                :fact nil
+                :env {}
+                :conditions-and-rules {[:test '(> ?t ?w)] #{[:query "my-test-query"]}}}
+               (-> e (ex-data))))


Generally we've used assert-ex-data in cases like this, the difference in behavior being that it just requires that some exception in the cause chain match the assertion, rather than the first one. This can make tests less brittle to failure when an exception is wrapped later for unrelated reasons. We don't have that functionality for the message though at this time, and I see value in testing the exception message since there is nontrivial logic there now. Also exceptions in e.g. the compiler would be more likely to be wrapped later, making such handling more important for tests aimed there. I'm OK with either keeping this as is or changing it along those lines; adding new test helpers here seems like scope creep.

It's not too difficult to make assert-ex-data also be able to assert the message, as an additional optional parameter, I'm going to make that change and submit it, it will make it easier to test both message and ex-data of nested exceptions in the future.

@WilliamParker i've made a small change to assert-ex-data to allow checking the message along with the data as well, and updated the existing test to use the new (assert-ex-data "message..." {...ex-data...} form).

+1 to those changes.

k13gomez force-pushed the throw-condition-node-exception branch from e7bdd1d to 4c1fca8 Compare December 21, 2021 16:39

k13gomez requested a review from EthanEChristian December 21, 2021 20:03

k13gomez linked an issue Dec 21, 2021 that may be closed by this pull request

Exceptions thrown in the rules engine during propagate-items-to-nodes need better debugging information #472

Closed

EthanEChristian reviewed Dec 22, 2021

View reviewed changes

k13gomez requested a review from EthanEChristian December 22, 2021 22:48

mrrodriguez self-requested a review December 23, 2021 04:37

mrrodriguez reviewed Dec 23, 2021

View reviewed changes

k13gomez changed the title ~~feat: throw condition node exception~~ feat: throw condition exception on TestNode exception Dec 23, 2021

WilliamParker reviewed Jan 3, 2022

View reviewed changes

k13gomez requested review from mrrodriguez and WilliamParker January 11, 2022 04:03

WilliamParker approved these changes Jan 17, 2022

View reviewed changes

feat: throw condition exception on TestNode exception

f59c847

k13gomez force-pushed the throw-condition-node-exception branch from 8ea7c0a to f59c847 Compare January 18, 2022 17:11

k13gomez merged commit cd88040 into oracle-samples:main Jan 18, 2022

k13gomez deleted the throw-condition-node-exception branch January 18, 2022 17:29

		(str "with bindings\n " bindings))
		facts-description (if-not (contains? args :fact)

feat: throw condition exception on TestNode exception #471

feat: throw condition exception on TestNode exception #471

Conversation

k13gomez commented Dec 20, 2021 • edited Loading

k13gomez commented Dec 20, 2021

EthanEChristian commented Dec 20, 2021 • edited Loading

k13gomez commented Dec 21, 2021 • edited Loading

k13gomez commented Dec 21, 2021 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

EthanEChristian commented Dec 22, 2021

k13gomez commented Dec 23, 2021

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

mrrodriguez 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

k13gomez commented Dec 23, 2021

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

k13gomez commented Jan 11, 2022

WilliamParker 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

k13gomez commented Dec 20, 2021 •

edited

Loading

EthanEChristian commented Dec 20, 2021 •

edited

Loading

k13gomez commented Dec 21, 2021 •

edited

Loading

k13gomez commented Dec 21, 2021 •

edited

Loading