Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Error reports returned as :cause string in an exception when produced by instrumentation within generative testing #160

Closed
WhittlesJr opened this issue May 24, 2019 · 11 comments
Closed

Error reports returned as :cause string in an exception when produced by instrumentation within generative testing #160

WhittlesJr opened this issue May 24, 2019 · 11 comments

Comments

@WhittlesJr
Copy link

My far-from-minimal reproduction:

(ns vertiv-common.demo-test
  (:require [clojure.spec.alpha :as s]
            [clojure.spec.test.alpha :as stest]
            [clojure.string :as str]
            [clojure.test :as test]
            [expound.alpha :as expound]
            [orchestra.core :refer [defn-spec]]
            [orchestra.spec.test :as orchestra]))

(alias 'stc 'clojure.spec.test.check)

(defn report-results [check-results]
  (let [checks-passed? (->> check-results (map :failure) (every? nil?))]
    (if checks-passed?
      (test/do-report {:type    :pass
                       :message (str "Generative tests pass for "
                                     (str/join ", " (map :sym check-results)))})
      (doseq [failed-check (filter :failure check-results)]
        (let [r       (stest/abbrev-result failed-check)
              failure (:failure r)]
          (test/do-report
           {:type     :fail
            :message  (binding [s/*explain-out* (expound/custom-printer
                                                 {:show-valid-values? true
                                                  :theme :figwheel-theme})]
                        (expound/explain-results-str check-results))
            :expected (->> r :spec rest (apply hash-map) :ret)
            :actual   (if (instance? #?(:clj Throwable :cljs js/Error) failure)
                        failure
                        (::stest/val failure))}))))
    checks-passed?))

(def default-opts {::stc/opts {:num-tests 50}})

#?(:clj
   (defmacro defspec-test
     ([name] `(defspec-test ~name (stest/checkable-syms) nil))
     ([name sym-or-syms] `(defspec-test ~name ~sym-or-syms default-opts))
     ([name sym-or-syms opts]
      (when test/*load-tests*
        `(defn ~(vary-meta name assoc :test
                           `(fn [] (report-results (stest/check ~sym-or-syms ~opts))))
           [] (test/test-var (var ~name)))))))

(defn check-spec-assertions [test-fn]
  (binding [s/*explain-out* (expound/custom-printer {:show-valid-values? true
                                                     :theme :figwheel-theme})]
    (s/check-asserts true)
    (test-fn)
    (s/check-asserts false)))

(defn instrument-all [test-fn]
  (binding [s/*explain-out* (expound/custom-printer {:show-valid-values? true
                                                     :theme :figwheel-theme})]
    (orchestra/instrument)
    (test-fn)
    (orchestra/unstrument)))

(test/use-fixtures :once
  check-spec-assertions
  instrument-all)

(defn-spec do-it-wrong boolean?
  [a int?] 1)

(defn-spec test-a-thing boolean?
  [thing int?]
  (do-it-wrong false)
  true)

(defspec-test gen_test-a-thing `test-a-thing)

Yields:

FAIL in vertiv-common.demo-test/gen_test-a-thing (demo_test.cljc:21)
== Checked vertiv-common.demo-test/test-a-thing 

  (vertiv-common.demo-test/test-a-thing -1)

 threw error

#error {
 :cause "Call to vertiv-common.demo-test/do-it-wrong did not conform to spec:\ndemo_test.cljc:68\n\n-- Spec failed --------------------\n\nFunction arguments\n\n  (false)\n   ^^^^^\n\nshould satisfy\n\n  int?\n\n-------------------------\nDetected 1 error\n"
 :data {:clojure.spec.alpha/problems [{:path [:args :a], :pred clojure.core/int?, :val false, :via [], :in [0]}], :clojure.spec.alpha/spec #object[clojure.spec.alpha$regex_spec_impl$reify__2509 0x2d8a45a "clojure.spec.alpha$regex_spec_impl$reify__2509@2d8a45a"], :clojure.spec.alpha/value (false), :clojure.spec.alpha/args (false), :clojure.spec.alpha/failure :instrument, :orchestra.spec.test/caller {:file "demo_test.cljc", :line 68, :var-scope vertiv-common.demo-test/test-a-thing}, :orchestra.spec/var #'vertiv-common.demo-test/do-it-wrong}
 :via
 [{:type clojure.lang.ExceptionInfo
   :message "Call to vertiv-common.demo-test/do-it-wrong did not conform to spec:\ndemo_test.cljc:68\n\n-- Spec failed --------------------\n\nFunction arguments\n\n  (false)\n   ^^^^^\n\nshould satisfy\n\n  int?\n\n-------------------------\nDetected 1 error\n"
   :data {:clojure.spec.alpha/problems [{:path [:args :a], :pred clojure.core/int?, :val false, :via [], :in [0]}], :clojure.spec.alpha/spec #object[clojure.spec.alpha$regex_spec_impl$reify__2509 0x2d8a45a "clojure.spec.alpha$regex_spec_impl$reify__2509@2d8a45a"], :clojure.spec.alpha/value (false), :clojure.spec.alpha/args (false), :clojure.spec.alpha/failure :instrument, :orchestra.spec.test/caller {:file "demo_test.cljc", :line 68, :var-scope vertiv-common.demo-test/test-a-thing}, :orchestra.spec/var #'vertiv-common.demo-test/do-it-wrong}                                                                                                                                                                                                                                                                             
   :at [orchestra.spec.test$spec_checking_fn$conform_BANG___4644 invoke "test.cljc" 115]}]
 :trace
 [[orchestra.spec.test$spec_checking_fn$conform_BANG___4644 invoke "test.cljc" 115]
  [orchestra.spec.test$spec_checking_fn$fn__4650 doInvoke "test.cljc" 126]
  [clojure.lang.RestFn invoke "RestFn.java" 408]
  [vertiv_common.demo_test$test_a_thing invokeStatic "demo_test.cljc" 68]
  [vertiv_common.demo_test$test_a_thing invoke "demo_test.cljc" 66]
... 
expected: boolean?
  actual: nil
1 tests, 1 assertions, 1 failures.
@bhb
Copy link
Owner

bhb commented May 24, 2019

@WhittlesJr Thanks for reporting this. I agree this is not great, but I'll have to think a bit about how to resolve.

Just for posterity (mostly for future self, so I don't forget my context), here is my sense of what's going on:

  • When an "instrumentation failure" occurs (i.e. we call an instrumented function the call does not match the spec), Clojure used to call *explain-out* to create a message, then put the result in the :message of the error
  • In 1.10, Clojure stopped doing this. Instead, it only includes the spec failure data, but doesn't call *explain-out* when constructing the error
  • Instead, the error is caught in the outer loop of the REPL. At that point, Clojure detects that it's a spec error and calls *explain-out* to format the error for the REPL
  • Orchestra still follows the old Clojure behavior of including a formatted :message. This makes it different from Clojure, which is both good and bad (for reasons I won't dive into here).
  • In this particular case, stest/check is doing some generative testing, which causes an exception (in particular, an instrumentation failure), so it doesn't bubble up to the top level to be printed as normal (since the error is captured and reported as a result of the test).

I'm not immediately clear to me what to do here. I suppose the best thing would be to write an exception printer similar to what Clojure does in the REPL?

https://github.com/clojure/clojure/blob/38524061dcb14c598c239be87184b3378ffc5bac/src/clj/clojure/main.clj#L269

I would need to think about how to best format this so it's clear that the exception is connected to the test failure.

I also want to ensure this works with:

  • Clojure 1.9
  • Clojure 1.10
  • Recent versions of CLJS
  • Orchestra and non-Orchestra

@WhittlesJr
Copy link
Author

Oh, if it matters, I'll add that this was run with kaocha from the command line (no REPL involved, but probably it doesn't make a difference).

@WhittlesJr
Copy link
Author

WhittlesJr commented May 31, 2019 •
edited
Loading

Hey @bhb, this is the solution needed for absolutely free generative testing! Looks like this issue still happens even under kaocha's new spec-test-check feature, but the repro for this issue can be reduced to :

(ns kaocha.demo-test
  (:require [orchestra.core :refer [defn-spec]]))

(defn-spec do-it-wrong boolean?
  [a int?] 1)

(defn-spec test-a-thing boolean?
  [thing int?]
  (do-it-wrong false)
  true)

And then run:

clojure -Atest -m kaocha.runner --plugin kaocha.plugin.alpha/spec-test-check --stc-instrumentation --stc-asserts

@bhb bhb added bug and removed bug labels Dec 11, 2019
@aviflax
Copy link

aviflax commented Jun 12, 2020

I’m wondering if maybe I’ve run into the same problem, or a variant of it.

I’m using Kaocha and Expound.

My tests.edn 
#kaocha/v1
{:tests [{:id         :examples
          :test-paths ["test/examples"]}
         {:id   :properties
          :type :kaocha.type/spec.test.check}]}
Terminal session with errors 
~/dev/dad $ bin/kaocha :examples
[()(.....E...E)(.......)]
Randomized with --seed 948299752

ERROR in dad.db.export.tables-test/split-record (alpha.clj:265)
Uncaught exception, not in assertion.
Exception: clojure.lang.ExceptionInfo: Call to expound.alpha/printer did not conform to spec:
alpha.clj:265

-- Spec failed --------------------

Function arguments

  (nil)
   ^^^

should satisfy

  map?

-------------------------
Detected 1 error

{:clojure.spec.alpha/problems [{:path [:args :explain-data], :pred clojure.core/map?, :val nil, :via [], :in [0]}], :clojure.spec.alpha/spec #object[clojure.spec.alpha$regex_spec_impl$reify__2519 0x2c9616bb "clojure.spec.alpha$regex_spec_impl$reify__2519@2c9616bb"], :clojure.spec.alpha/value (nil), :clojure.spec.alpha/args (nil), :clojure.spec.alpha/failure :instrument, :orchestra.spec.test/caller {:file "alpha.clj", :line 265, :var-scope clojure.spec.alpha/explain-out}, :orchestra.spec/var #'expound.alpha/printer}
 at orchestra.spec.test$spec_checking_fn$conform_BANG___3123.invoke (test.cljc:115)
    ...
    clojure.spec.alpha$explain_out.invokeStatic (alpha.clj:265)
    clojure.spec.alpha$explain_out.invoke (alpha.clj:261)
    clojure.spec.alpha$explain.invokeStatic (alpha.clj:270)
    clojure.spec.alpha$explain.invoke (alpha.clj:267)
    clojure.spec.alpha$explain_str.invokeStatic (alpha.clj:275)
    clojure.spec.alpha$explain_str.invoke (alpha.clj:272)
    dad.db.export.tables_test$fn__7233.invokeStatic (tables_test.clj:146)
    dad.db.export.tables_test/fn (tables_test.clj:84)
    kaocha.plugin.capture_output$capture_output_pre_test_hook$fn__2584$fn__2585.invoke (capture_output.clj:92)
    kaocha.type.var$eval9488$fn__9490$fn__9495.invoke (var.clj:30)
    kaocha.type.var$eval9488$fn__9490.invoke (var.clj:27)
    ...
    kaocha.plugin.capture_output$capture_output_wrap_run_hook$fn__2576$fn__2577.invoke (capture_output.clj:83)
    ...
    kaocha.plugin.capture_output$capture_output_wrap_run_hook$fn__2576.doInvoke (capture_output.clj:83)
    ...
    kaocha.testable$run.invokeStatic (testable.clj:120)
    kaocha.testable$run.invoke (testable.clj:111)
    ...
    kaocha.testable$run_testable.invokeStatic (testable.clj:200)
    kaocha.testable$run_testable.invoke (testable.clj:149)
    kaocha.testable$run_testables.invokeStatic (testable.clj:213)
    kaocha.testable$run_testables.invoke (testable.clj:203)
    ...
    kaocha.type.ns$run_tests$fn__3365.invoke (ns.clj:21)
    ...
    kaocha.type.ns$run_tests.invokeStatic (ns.clj:21)
    kaocha.type.ns$run_tests.invoke (ns.clj:17)
    kaocha.type.ns$eval3383$fn__3384.invoke (ns.clj:64)
    ...
    kaocha.plugin.capture_output$capture_output_wrap_run_hook$fn__2576$fn__2577.invoke (capture_output.clj:83)
    ...
    kaocha.plugin.capture_output$capture_output_wrap_run_hook$fn__2576.doInvoke (capture_output.clj:83)
    ...
    kaocha.testable$run.invokeStatic (testable.clj:120)
    kaocha.testable$run.invoke (testable.clj:111)
    ...
    kaocha.testable$run_testable.invokeStatic (testable.clj:200)
    kaocha.testable$run_testable.invoke (testable.clj:149)
    kaocha.testable$run_testables.invokeStatic (testable.clj:213)
    kaocha.testable$run_testables.invoke (testable.clj:203)
    kaocha.test_suite$run.invokeStatic (test_suite.clj:7)
    kaocha.test_suite$run.invoke (test_suite.clj:5)
    kaocha.type.clojure.test$eval4790$fn__4791.invoke (test.clj:20)
    ...
    kaocha.plugin.capture_output$capture_output_wrap_run_hook$fn__2576$fn__2577.invoke (capture_output.clj:83)
    ...
    kaocha.plugin.capture_output$capture_output_wrap_run_hook$fn__2576.doInvoke (capture_output.clj:83)
    ...
    kaocha.testable$run.invokeStatic (testable.clj:120)
    kaocha.testable$run.invoke (testable.clj:111)
    ...
    kaocha.testable$run_testable.invokeStatic (testable.clj:200)
    kaocha.testable$run_testable.invoke (testable.clj:149)
    kaocha.testable$run_testables.invokeStatic (testable.clj:213)
    kaocha.testable$run_testables.invoke (testable.clj:203)
    kaocha.api$run$fn__3073$fn__3074$fn__3075.invoke (api.clj:106)
    ...
    kaocha.api$run$fn__3073$fn__3074.invoke (api.clj:98)
    ...
    kaocha.api$run$fn__3073.invoke (api.clj:97)
    ...
    kaocha.api$run.invokeStatic (api.clj:83)
    kaocha.api$run.invoke (api.clj:71)
    kaocha.runner$run.invokeStatic (runner.clj:129)
    kaocha.runner$run.invoke (runner.clj:71)
    kaocha.runner$_main_STAR_.invokeStatic (runner.clj:162)
    kaocha.runner$_main_STAR_.doInvoke (runner.clj:141)
    ...
    kaocha.runner$_main.invokeStatic (runner.clj:173)
    kaocha.runner$_main.doInvoke (runner.clj:171)
    ...

ERROR in dad.db.export.tables-test/recordset->tables (alpha.clj:265)
Uncaught exception, not in assertion.
Exception: clojure.lang.ExceptionInfo: Call to expound.alpha/printer did not conform to spec:
alpha.clj:265

-- Spec failed --------------------

Function arguments

  (nil)
   ^^^

should satisfy

  map?

-------------------------
Detected 1 error

{:clojure.spec.alpha/problems [{:path [:args :explain-data], :pred clojure.core/map?, :val nil, :via [], :in [0]}], :clojure.spec.alpha/spec #object[clojure.spec.alpha$regex_spec_impl$reify__2519 0x2c9616bb "clojure.spec.alpha$regex_spec_impl$reify__2519@2c9616bb"], :clojure.spec.alpha/value (nil), :clojure.spec.alpha/args (nil), :clojure.spec.alpha/failure :instrument, :orchestra.spec.test/caller {:file "alpha.clj", :line 265, :var-scope clojure.spec.alpha/explain-out}, :orchestra.spec/var #'expound.alpha/printer}
 at orchestra.spec.test$spec_checking_fn$conform_BANG___3123.invoke (test.cljc:115)
    ...
    clojure.spec.alpha$explain_out.invokeStatic (alpha.clj:265)
    clojure.spec.alpha$explain_out.invoke (alpha.clj:261)
    clojure.spec.alpha$explain.invokeStatic (alpha.clj:270)
    clojure.spec.alpha$explain.invoke (alpha.clj:267)
    clojure.spec.alpha$explain_str.invokeStatic (alpha.clj:275)
    clojure.spec.alpha$explain_str.invoke (alpha.clj:272)
    dad.db.export.tables_test$fn__7250$fn__7255.invoke (tables_test.clj:165)
    dad.db.export.tables_test$fn__7250.invokeStatic (tables_test.clj:165)
    dad.db.export.tables_test/fn (tables_test.clj:148)
    kaocha.plugin.capture_output$capture_output_pre_test_hook$fn__2584$fn__2585.invoke (capture_output.clj:92)
    kaocha.type.var$eval9488$fn__9490$fn__9495.invoke (var.clj:30)
    kaocha.type.var$eval9488$fn__9490.invoke (var.clj:27)
    ...
    kaocha.plugin.capture_output$capture_output_wrap_run_hook$fn__2576$fn__2577.invoke (capture_output.clj:83)
    ...
    kaocha.plugin.capture_output$capture_output_wrap_run_hook$fn__2576.doInvoke (capture_output.clj:83)
    ...
    kaocha.testable$run.invokeStatic (testable.clj:120)
    kaocha.testable$run.invoke (testable.clj:111)
    ...
    kaocha.testable$run_testable.invokeStatic (testable.clj:200)
    kaocha.testable$run_testable.invoke (testable.clj:149)
    kaocha.testable$run_testables.invokeStatic (testable.clj:213)
    kaocha.testable$run_testables.invoke (testable.clj:203)
    ...
    kaocha.type.ns$run_tests$fn__3365.invoke (ns.clj:21)
    ...
    kaocha.type.ns$run_tests.invokeStatic (ns.clj:21)
    kaocha.type.ns$run_tests.invoke (ns.clj:17)
    kaocha.type.ns$eval3383$fn__3384.invoke (ns.clj:64)
    ...
    kaocha.plugin.capture_output$capture_output_wrap_run_hook$fn__2576$fn__2577.invoke (capture_output.clj:83)
    ...
    kaocha.plugin.capture_output$capture_output_wrap_run_hook$fn__2576.doInvoke (capture_output.clj:83)
    ...
    kaocha.testable$run.invokeStatic (testable.clj:120)
    kaocha.testable$run.invoke (testable.clj:111)
    ...
    kaocha.testable$run_testable.invokeStatic (testable.clj:200)
    kaocha.testable$run_testable.invoke (testable.clj:149)
    kaocha.testable$run_testables.invokeStatic (testable.clj:213)
    kaocha.testable$run_testables.invoke (testable.clj:203)
    kaocha.test_suite$run.invokeStatic (test_suite.clj:7)
    kaocha.test_suite$run.invoke (test_suite.clj:5)
    kaocha.type.clojure.test$eval4790$fn__4791.invoke (test.clj:20)
    ...
    kaocha.plugin.capture_output$capture_output_wrap_run_hook$fn__2576$fn__2577.invoke (capture_output.clj:83)
    ...
    kaocha.plugin.capture_output$capture_output_wrap_run_hook$fn__2576.doInvoke (capture_output.clj:83)
    ...
    kaocha.testable$run.invokeStatic (testable.clj:120)
    kaocha.testable$run.invoke (testable.clj:111)
    ...
    kaocha.testable$run_testable.invokeStatic (testable.clj:200)
    kaocha.testable$run_testable.invoke (testable.clj:149)
    kaocha.testable$run_testables.invokeStatic (testable.clj:213)
    kaocha.testable$run_testables.invoke (testable.clj:203)
    kaocha.api$run$fn__3073$fn__3074$fn__3075.invoke (api.clj:106)
    ...
    kaocha.api$run$fn__3073$fn__3074.invoke (api.clj:98)
    ...
    kaocha.api$run$fn__3073.invoke (api.clj:97)
    ...
    kaocha.api$run.invokeStatic (api.clj:83)
    kaocha.api$run.invoke (api.clj:71)
    kaocha.runner$run.invokeStatic (runner.clj:129)
    kaocha.runner$run.invoke (runner.clj:71)
    kaocha.runner$_main_STAR_.invokeStatic (runner.clj:162)
    kaocha.runner$_main_STAR_.doInvoke (runner.clj:141)
    ...
    kaocha.runner$_main.invokeStatic (runner.clj:173)
    kaocha.runner$_main.doInvoke (runner.clj:171)
    ...
7 tests, 17 assertions, 2 errors, 0 failures.

A few notes:

  • My tests.edn defines the Kaocha test suites :examples and :properties
    • :properties is a sort of “virtual” test suite generated by a Kaocha plugin
  • On the command line I’ve run bin/kaocha :examples to run only that suite
  • None of my code currently uses expound or instrumentation (it’s commented out for now)
  • I’ve found one way to run :examples without the above errors occuring: if I comment out the
    definition of :properties in tests.edn and then run :examples from within a REPL
    • In the REPL, I run (use 'kaocha.repl) (run :examples)
    • All the tests then run pass successfully
    • Oddly, even with that suite commented out, if I run bin/kaocha :examples from the command line
      I still get the above error output. I find this perplexing.

Now that I’ve written all this out, I’m starting to think I should open an issue with Kaocha, but
I’m still curious whether y’all think that what I’m seeing is a version of the same problem?

Thank you!

@aviflax
Copy link

aviflax commented Jun 15, 2020

Quick follow-up, I’ve found a possible clue as to what’s been happening in my project:

I’d wanted to use :print-specs? false by default, so instead of calling expound.alpha/expound-str I was setting s/*explain-out* to the result of calling expound/custom-printer and then in my tests I was using s/explain-str

I just discovered that switching those explain-str calls expound-str and supplying the same set of opts I was passing to custom-printer does not trigger the problem I described above.

I don’t know why/how exactly, but it seems maybe there’s some issue with the combination of providing an expound printer to clojure.spec and then calling explain-str … possible when combined with Kaocha and/or Orchestra…? 😬 I don’t actually have a clue…

@bhb
Copy link
Owner

bhb commented Jun 17, 2020

@aviflax Thanks for the info! I appreciate it. I'm super busy right now, but as soon as I get some cycles, I'll dig into this a bit more and see if I can isolate it.

@bhb
Copy link
Owner

bhb commented Jun 17, 2020

@aviflax Actually, I think you may be running into a different bug #191

Can you try one of two things?

  1. If you can rely on a specific SHA of Expound easily, can you test out 391e45f ?
  2. If not, can you try the workaround mentioned here?

@aviflax
Copy link

aviflax commented Jun 17, 2020

Yup, I’ll give those a try tomorrow. Thanks!

@aviflax
Copy link

aviflax commented Jun 17, 2020

Yup, 391e45f seems to have resolved the problem. Thank you!

I can use this version of the code for now; using gitlibs via tools.deps is my normal modus operandi so it’s really no big deal. That said, it’s one more thing I have to document and explain in the deps.edn file, so if you can maybe get this into the main branch at some point, and ideally maybe even a tagged release, that’d be excellent! No rush though.

Thanks Ben!

@bhb
Copy link
Owner

bhb commented Oct 2, 2020

@aviflax Sorry for the delayed reply, but this was fixed in 0.8.5

@aviflax
Copy link

aviflax commented Oct 2, 2020

No worries — thanks for letting me know!

@bhb bhb closed this as completed Dec 1, 2020
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@bhb @aviflax @WhittlesJr