Exceptions thrown in tests cause an error

sheluchin commented 1 year ago

(ns foo
  (:require [clojure.test :as t]))

(t/deftest foo-test
  (t/is (= 1 (throw (Exception.)))))

When this test is executed with <Leader>tn (IcedTestNs), first the Testing: foo message comes up, but it doesn't go away. Eventually, the REPL shows an error like this:

Exception in thread "nREPL-session-295b49c0-e6cb-47e2-880f-2a3812ab8878" java.lang.ClassCastException: class clojure.lang.Symbol cannot be cast to class clojure.lang.IPersistentVector (clojure.lang.Symbol and clojure.lang.IPersistentVector are in unnamed module of loader 'app')
    at clojure.lang.APersistentVector.compareTo(APersistentVector.java:435)
    at clojure.lang.Util.compare(Util.java:153)
    at clojure.core$compare.invokeStatic(core.clj:842)
    at clojure.core$compare.invoke(core.clj:833)
    at clojure.lang.AFunction.compare(AFunction.java:51)
    at java.base/java.util.TimSort.binarySort(TimSort.java:296)
    at java.base/java.util.TimSort.sort(TimSort.java:239)
    at java.base/java.util.Arrays.sort(Arrays.java:1441)
    at clojure.core$sort.invokeStatic(core.clj:3116)
    at clojure.core$sort.invokeStatic(core.clj:3103)
    at clojure.core$sort.invoke(core.clj:3103)
    at cider.nrepl.inlined_deps.orchard.v0v9v2.orchard.namespace$classpath_namespaces.invokeStatic(namespace.clj:123)
    at cider.nrepl.inlined_deps.orchard.v0v9v2.orchard.namespace$classpath_namespaces.invoke(namespace.clj:114)
    at cider.nrepl.inlined_deps.orchard.v0v9v2.orchard.namespace$project_namespaces.invokeStatic(namespace.clj:135)
    at cider.nrepl.inlined_deps.orchard.v0v9v2.orchard.namespace$project_namespaces.invoke(namespace.clj:127)
    at cider.nrepl.middleware.stacktrace$directory_namespaces.invokeStatic(stacktrace.clj:132)
    at cider.nrepl.middleware.stacktrace$directory_namespaces.invoke(stacktrace.clj:122)
    at cider.nrepl.middleware.test$report_fixture_error.invokeStatic(test.clj:216)
    at cider.nrepl.middleware.test$report_fixture_error.invoke(test.clj:211)
    at cider.nrepl.middleware.test$test_vars.invokeStatic(test.clj:259)
    at cider.nrepl.middleware.test$test_vars.invoke(test.clj:248)
    at cider.nrepl.middleware.test$test_ns.invokeStatic(test.clj:270)
    at cider.nrepl.middleware.test$test_ns.invoke(test.clj:261)
    at cider.nrepl.middleware.test$test_var_query.invokeStatic(test.clj:281)
    at cider.nrepl.middleware.test$test_var_query.invoke(test.clj:274)
    at cider.nrepl.middleware.test$handle_test_var_query_op$fn__66760$fn__66761.invoke(test.clj:319)
    at clojure.lang.AFn.applyToHelper(AFn.java:152)
    at clojure.lang.AFn.applyTo(AFn.java:144)
    at clojure.core$apply.invokeStatic(core.clj:667)
    at clojure.core$with_bindings_STAR_.invokeStatic(core.clj:1990)
    at clojure.core$with_bindings_STAR_.doInvoke(core.clj:1990)
    at clojure.lang.RestFn.invoke(RestFn.java:425)
    at cider.nrepl.middleware.test$handle_test_var_query_op$fn__66760.invoke(test.clj:311)
    at clojure.lang.AFn.run(AFn.java:22)
    at nrepl.middleware.session$session_exec$main_loop__37462$fn__37466.invoke(session.clj:218)
    at nrepl.middleware.session$session_exec$main_loop__37462.invoke(session.clj:217)
    at clojure.lang.AFn.run(AFn.java:22)
    at java.base/java.lang.Thread.run(Thread.java:829)

liquidz commented 1 year ago

@sheluchin Thanks for your reporting!

I could not reproduce the problem in my environment...

Steps I tested are here:

$ vim foo.clj
Execute :IcedConnect
Execute :IcedTestNs

Directory tree:

deps.edn

{:paths ["src"]
:deps {org.clojure/clojure {:mvn/version "1.11.1"}}}

src/
- foo.clj

Could you try following steps and please tell me the results of :messages?

$ vim foo.clj or $ nvim foo.clj
Execute :IcedConnect
Execute :let g:iced#debug = v:true to enable debug mode
Execute :IcedTestNs

For example, :messages could look like follows:

Connected.
DEBUG >>>: {'file': '(ns foo^@  (:require^@    [clojure.test :as t]))^@^@(t/deftest foo-test^@  (t/is (= 1 (throw (Exception.)))))', 'id': 6, 'file-name': 'src/foo.clj', 'callback': function('<lambda>167'), 'session': '42d085dc-b204-4b74-9ce9-8fe84a57be16', 'op': 'load-file', 'file-path': '/private/tmp/foo/src/foo.clj'}
DEBUG >>>: {'file': '/private/tmp/foo/src/foo.clj', 'id': 7, 'nrepl.middleware.print/stream?': 1, 'verbose': v:false, 'column': 7, 'line': 1, 'code': '(clojure.core/require ''foo)', 'session': '42d085dc-b204-4b74-9ce9-8fe84a57be16', 'ns': 'foo', 'op': 'eval', 'callback': function('<lambda>170')}
DEBUG <<<: d2:idi7e7:session36:42d085dc-b204-4b74-9ce9-8fe84a57be165:value3:niled2:idi7e2:ns3:foo7:session36:42d085dc-b204-4b74-9ce9-8fe84a57be16e
DEBUG <<<: d2:idi7e7:session36:42d085dc-b204-4b74-9ce9-8fe84a57be166:statusl4:doneee
DEBUG >>>: {'callback': function('<80><fd>R179__resolve', [{'_rejections': [], 'then': function('<80><fd>R179__promise_then'), '_state': 0, '_vital_promise': 11, '_children': [], '_result': v:null, 'catch': function('<80><fd>R179__promise_catch'), '_fulfillments': [], '_has_floating_child': v:false, 'finally': function('<80><fd>R179__promise_finally')}]), 'verbose': v:false, 'session': '42d085dc-b204-4b74-9ce9-8fe84a57be16', 'ns': 'foo', 'op': 'ns-vars-with-meta'}
DEBUG <<<: d2:idi6e7:session36:42d085dc-b204-4b74-9ce9-8fe84a57be165:value14:#'foo/foo-teste
DEBUG <<<: d2:idi6e7:session36:42d085dc-b204-4b74-9ce9-8fe84a57be166:statusl4:doneee
Required.
DEBUG <<<: d17:ns-vars-with-metad8:foo-testd4:test24:#function[foo/fn--10978]ee7:session36:42d085dc-b204-4b74-9ce9-8fe84a57be166:statusl4:doneee
DEBUG start: ex_cmd
DEBUG start: sign
DEBUG >>>: {'callback': function('<80><fd>R179__resolve', [{'_rejections': [], 'then': function('<80><fd>R179__promise_then'), '_state': 0, '_vital_promise': 12, '_children': [], '_result': v:null, 'catch': function('<80><fd>R179__promise_catch'), '_fulfillments': [], '_has_floating_child': v:false, 'finally': function('<80><fd>R179__promise_finally')}]), 'session': '42d085dc-b204-4b74-9ce9-8fe84a57be16', 'ns': 'foo', 'op': 'ns-path'}
DEBUG <<<: d4:path33:file:/private/tmp/foo/src/foo.clj7:session36:42d085dc-b204-4b74-9ce9-8fe84a57be166:statusl4:doneee
Testing: foo
DEBUG >>>: {'file': '/private/tmp/foo/src/foo.clj', 'id': 8, 'nrepl.middleware.print/stream?': 1, 'verbose': v:false, 'column': 7, 'line': 1, 'code': '(clojure.core/require ''foo)', 'session': '42d085dc-b204-4b74-9ce9-8fe84a57be16', 'ns': 'foo', 'op': 'eval', 'callback': function('<lambda>190')}
DEBUG <<<: d2:idi8e7:session36:42d085dc-b204-4b74-9ce9-8fe84a57be165:value3:niled2:idi8e2:ns3:foo7:session36:42d085dc-b204-4b74-9ce9-8fe84a57be16e
DEBUG <<<: d2:idi8e7:session36:42d085dc-b204-4b74-9ce9-8fe84a57be166:statusl4:doneee
DEBUG >>>: {'id': 9, 'callback': function('<80><fd>R197___clojure_test_out'), 'session': '42d085dc-b204-4b74-9ce9-8fe84a57be16', 'op': 'test-var-query', 'var-query': {'ns-query': {'exactly': ['foo']}}}
DEBUG <<<: d9:gen-inputle2:idi9e7:resultsd3:food8:foo-testld7:contextle5:error19:java.lang.Exception8:expected27:(= 1 (throw (Exception.)))^@4:file11:src/foo.clj5:indexi0e4:linei6e7:message0:2:ns3:foo4:type5:error3:var8:foo-testeeee7:session36:42d085dc-b204-4b74-9ce9-8fe84a57be167:summaryd5:errori1e4:faili0e2:nsi1e4:passi0e4:testi1e3:vari1ee10:testing-ns3:fooe
DEBUG <<<: d2:idi9e7:session36:42d085dc-b204-4b74-9ce9-8fe84a57be166:statusl4:doneee
DEBUG start: quickfix
foo: Ran 1 assertions, in 1 test functions. 0 failures, 1 errors.

sheluchin commented 1 year ago

Hmm, I couldn't reproduce in a minimal project either, but it happens consistently in my actual project. Here is the debug log:

Connected.
Wait a minute. It may take some time.
CLJS repl has started.
DEBUG >>>: {'file': '(ns foo^@  (:require [clojure.test :as t]))^@^@(t/deftest foo-test^@  (t/is (= 1 (throw (Exception.)))))', 'id': 52, 'file-name': 'foo.clj', 'callback': function('<lambda
>10883'), 'session': '79ef0c90-2a6b-4bf0-9b2c-ebdff19d3891', 'op': 'load-file', 'file-path': '... /foo.clj'}
DEBUG >>>: {'file': '... /foo.clj', 'id': 53, 'nrepl.middleware.print/stream?': 1, 'verbose': v:false, 'column': 1, 'line': 3, 'code': '(clojure.core/req
uire ''foo)', 'session': '79ef0c90-2a6b-4bf0-9b2c-ebdff19d3891', 'ns': 'foo', 'op': 'eval', 'callback': function('<lambda>10886')}
DEBUG <<<: d2:idi52e7:session36:79ef0c90-2a6b-4bf0-9b2c-ebdff19d38915:value14:#'foo/foo-tested2:idi52e7:session36:79ef0c90-2a6b-4bf0-9b2c-ebdff19d38916:statusl4:doneeed2:idi53e7:session36:79e
f0c90-2a6b-4bf0-9b2c-ebdff19d38915:value3:niled2:idi53e2:ns3:foo7:session36:79ef0c90-2a6b-4bf0-9b2c-ebdff19d3891ed2:idi53e7:session36:79ef0c90-2a6b-4bf0-9b2c-ebdff19d38916:statusl4:doneee
Required.
DEBUG >>>: {'callback': function('<80><fd>R244__resolve', [{'_rejections': [], 'then': function('<80><fd>R244__promise_then'), '_state': 0, '_vital_promise': 257, '_children': [], '_result':
v:null, 'catch': function('<80><fd>R244__promise_catch'), '_fulfillments': [], '_has_floating_child': v:false, 'finally': function('<80><fd>R244__promise_finally')}]), 'verbose': v:false, 'se
ssion': '79ef0c90-2a6b-4bf0-9b2c-ebdff19d3891', 'ns': 'foo', 'op': 'ns-vars-with-meta'}
DEBUG <<<: d17:ns-vars-with-metad8:foo-testd4:test26:#function[foo/fn--1321287]ee7:session36:79ef0c90-2a6b-4bf0-9b2c-ebdff19d38916:statusl4:doneee
DEBUG >>>: {'callback': function('<80><fd>R244__resolve', [{'_rejections': [], 'then': function('<80><fd>R244__promise_then'), '_state': 0, '_vital_promise': 258, '_children': [], '_result':
v:null, 'catch': function('<80><fd>R244__promise_catch'), '_fulfillments': [], '_has_floating_child': v:false, 'finally': function('<80><fd>R244__promise_finally')}]), 'session': '79ef0c90-2a
6b-4bf0-9b2c-ebdff19d3891', 'ns': 'foo', 'op': 'ns-path'}
DEBUG <<<: d4:path0:7:session36:79ef0c90-2a6b-4bf0-9b2c-ebdff19d38916:statusl4:doneee
Testing: foo
DEBUG >>>: {'file': '... /foo.clj', 'id': 54, 'nrepl.middleware.print/stream?': 1, 'verbose': v:false, 'column': 1, 'line': 3, 'code': '(clojure.core/req
uire ''foo)', 'session': '79ef0c90-2a6b-4bf0-9b2c-ebdff19d3891', 'ns': 'foo', 'op': 'eval', 'callback': function('<lambda>11004')}
DEBUG <<<: d2:idi54e7:session36:79ef0c90-2a6b-4bf0-9b2c-ebdff19d38915:value3:niled2:idi54e2:ns3:foo7:session36:79ef0c90-2a6b-4bf0-9b2c-ebdff19d3891ed2:idi54e7:session36:79ef0c90-2a6b-4bf0-9b2
c-ebdff19d38916:statusl4:doneee
DEBUG >>>: {'id': 55, 'callback': function('<80><fd>R272___clojure_test_out'), 'session': '79ef0c90-2a6b-4bf0-9b2c-ebdff19d3891', 'op': 'test-var-query', 'var-query': {'ns-query': {'exactly':
 ['foo']}}}
Press ENTER or type command to continue

Any idea what could be happening here?

liquidz commented 1 year ago

CLJS repl has started.

You are working with foo.clj, but it seems that vim-iced connected to ClojureScript's nREPL🤔 Would this be reproducible with Clojure's nREPL?

sheluchin commented 1 year ago

Yes, it works correctly when launching the repl with just iced repl and no other ooptions.

Maybe something in my workflow is wrong? I've been using it like this for a while and things mostly seem to work.

Could you please suggest if I'm connecting the wrong way? My project is based on fulcro-rad-template: deps.edn, shadow-cljs.edn. It is a full-stack thing with a CLJS and CLJ. When I connect to it, I start iced repl like this:

;; aliases not exactly as in fulcro-rad-template
iced repl :main --force-shadow-cljs -A:dev:shadow-cljs:test:cards:repl/reveal

and once it's running, I just use :IcedConnect. Then when I switch between clj/cljs with :IcedCycleSession and require things as necessary. Things mostly work, but sometimes I run into small issues that I've been working around.

Is there something I can do better to use vim-iced with project like this?

sheluchin commented 1 year ago

So, I did some investigating this morning.

It turns out to be a little more tricky than I first thought, and not really related to the way I start my REPL and connect to it.

Basically, if you include this specific repo in :extra-paths, tests which throw an exception will no longer work, regardless of how you connect to it. I had a few hundred repos, none of them caused any issue, but when I added this particular one, tests stopped working.

liquidz commented 1 year ago

@sheluchin Thanks for your confirmation! I could reproduce the exception with oakes/Lightmod. It seems that exception is thrown when resources/templates is in :paths or :extra-paths.

*.clj files in this directory may be the cause.

sheluchin commented 1 year ago

@liquidz Thank you for checking that. I believe this is a vim-iced bug because just being in :paths or :extra-paths shouldn't cause code to be evaluated. I can not reproduce the issue directly in the REPL while vim-iced has this unexpected behaviour. Here's a test in the same REPL, first the vim-iced interaction and then directly typing into the REPL:

/tmp/iced445$ iced repl
OK: Clojure CLI project is detected
nREPL server started on port 42863 on host 127.0.0.1 - nrepl://127.0.0.1:42863
nREPL 1.0.0
Clojure 1.11.1
OpenJDK 64-Bit Server VM 11.0.16+8-post-Ubuntu-0ubuntu122.04
Interrupt: Control+C
Exit:      Control+D or (exit) or (quit)
user=> Exception in thread "nREPL-session-de327bf8-2676-476a-a267-04eef9474e23" java.lang.ClassCastException: class clojure.lang.Symbol cannot be cast to class clojure.lang.IPersistentVect
or (clojure.lang.Symbol and clojure.lang.IPersistentVector are in unnamed module of loader 'app')
        at clojure.lang.APersistentVector.compareTo(APersistentVector.java:435)
        at clojure.lang.Util.compare(Util.java:153)
        at clojure.core$compare.invokeStatic(core.clj:842)
        at clojure.core$compare.invoke(core.clj:833)
        at clojure.lang.AFunction.compare(AFunction.java:51)
        at java.base/java.util.TimSort.countRunAndMakeAscending(TimSort.java:360)
        at java.base/java.util.TimSort.sort(TimSort.java:220)
        at java.base/java.util.Arrays.sort(Arrays.java:1441)
        at clojure.core$sort.invokeStatic(core.clj:3116)
        at clojure.core$sort.invokeStatic(core.clj:3103)
        at clojure.core$sort.invoke(core.clj:3103)
        at cider.nrepl.inlined_deps.orchard.v0v9v2.orchard.namespace$classpath_namespaces.invokeStatic(namespace.clj:123)
        at cider.nrepl.inlined_deps.orchard.v0v9v2.orchard.namespace$classpath_namespaces.invoke(namespace.clj:114)
        at cider.nrepl.inlined_deps.orchard.v0v9v2.orchard.namespace$project_namespaces.invokeStatic(namespace.clj:135)
        at cider.nrepl.inlined_deps.orchard.v0v9v2.orchard.namespace$project_namespaces.invoke(namespace.clj:127)
        at cider.nrepl.middleware.stacktrace$directory_namespaces.invokeStatic(stacktrace.clj:132)
        at cider.nrepl.middleware.stacktrace$directory_namespaces.invoke(stacktrace.clj:122)
        at cider.nrepl.middleware.test$report_fixture_error.invokeStatic(test.clj:216)
        at cider.nrepl.middleware.test$report_fixture_error.invoke(test.clj:211)
        at cider.nrepl.middleware.test$test_vars.invokeStatic(test.clj:259)
        at cider.nrepl.middleware.test$test_vars.invoke(test.clj:248)
        at cider.nrepl.middleware.test$test_ns.invokeStatic(test.clj:270)
        at cider.nrepl.middleware.test$test_ns.invoke(test.clj:261)
        at cider.nrepl.middleware.test$test_var_query.invokeStatic(test.clj:281)
        at cider.nrepl.middleware.test$test_var_query.invoke(test.clj:274)
        at cider.nrepl.middleware.test$handle_test_var_query_op$fn__10644$fn__10645.invoke(test.clj:319)
        at clojure.lang.AFn.applyToHelper(AFn.java:152)
        at clojure.lang.AFn.applyTo(AFn.java:144)
        at clojure.core$apply.invokeStatic(core.clj:667)
        at clojure.core$with_bindings_STAR_.invokeStatic(core.clj:1990)
        at clojure.core$with_bindings_STAR_.doInvoke(core.clj:1990)
        at clojure.lang.RestFn.invoke(RestFn.java:425)
        at cider.nrepl.middleware.test$handle_test_var_query_op$fn__10644.invoke(test.clj:311)
        at clojure.lang.AFn.run(AFn.java:22)
        at nrepl.middleware.session$session_exec$main_loop__1368$fn__1372.invoke(session.clj:218)
        at nrepl.middleware.session$session_exec$main_loop__1368.invoke(session.clj:217)
        at clojure.lang.AFn.run(AFn.java:22)
        at java.base/java.lang.Thread.run(Thread.java:829)

:x
:x
user=> (require 'foo)
nil
user=> (use 'clojure.test)
nil
user=> (run-tests 'foo)

Testing foo

ERROR in (foo-test) (src/foo.clj:5)
expected: (= 2 (throw (ex-info "x" {})))
  actual: clojure.lang.ExceptionInfo: x
{}
 at foo$fn__10277.invokeStatic (src/foo.clj:5)
    foo/fn (src/foo.clj:5)
    clojure.test$test_var$fn__9856.invoke (test.clj:717)
    clojure.test$test_var.invokeStatic (test.clj:717)
    clojure.test$test_var.invoke (test.clj:708)
    clojure.test$test_vars$fn__9882$fn__9887.invoke (test.clj:735)
    clojure.test$default_fixture.invokeStatic (test.clj:687)
    clojure.test$default_fixture.invoke (test.clj:683)
    clojure.test$test_vars$fn__9882.invoke (test.clj:735)
    clojure.test$default_fixture.invokeStatic (test.clj:687)
    clojure.test$default_fixture.invoke (test.clj:683)
    clojure.test$test_vars.invokeStatic (test.clj:731)
    clojure.test$test_all_vars.invokeStatic (test.clj:737)
    clojure.test$test_ns.invokeStatic (test.clj:758)
    clojure.test$test_ns.invoke (test.clj:743)
    clojure.core$map$fn__5935.invoke (core.clj:2772)
    clojure.lang.LazySeq.sval (LazySeq.java:42)
    clojure.lang.LazySeq.seq (LazySeq.java:51)
    clojure.lang.Cons.next (Cons.java:39)
    clojure.lang.RT.boundedLength (RT.java:1790)
    clojure.lang.RestFn.applyTo (RestFn.java:130)
    clojure.core$apply.invokeStatic (core.clj:669)
    clojure.test$run_tests.invokeStatic (test.clj:768)
    clojure.test$run_tests.doInvoke (test.clj:768)
    clojure.lang.RestFn.invoke (RestFn.java:408)
    user$eval10708.invokeStatic (NO_SOURCE_FILE:1)
    user$eval10708.invoke (NO_SOURCE_FILE:1)
    clojure.lang.Compiler.eval (Compiler.java:7194)
    clojure.lang.Compiler.eval (Compiler.java:7149)
    clojure.core$eval.invokeStatic (core.clj:3215)
    clojure.core$eval.invoke (core.clj:3211)
    nrepl.middleware.interruptible_eval$evaluate$fn__1265$fn__1266.invoke (interruptible_eval.clj:87)
    clojure.lang.AFn.applyToHelper (AFn.java:152)
    clojure.lang.AFn.applyTo (AFn.java:144)
    clojure.core$apply.invokeStatic (core.clj:667)
    clojure.core$with_bindings_STAR_.invokeStatic (core.clj:1990)
    clojure.core$with_bindings_STAR_.doInvoke (core.clj:1990)
    clojure.lang.RestFn.invoke (RestFn.java:425)
    nrepl.middleware.interruptible_eval$evaluate$fn__1265.invoke (interruptible_eval.clj:87)
    clojure.main$repl$read_eval_print__9206$fn__9209.invoke (main.clj:437)
    clojure.main$repl$read_eval_print__9206.invoke (main.clj:437)
    clojure.main$repl$fn__9215.invoke (main.clj:458)
    clojure.main$repl.invokeStatic (main.clj:458)
    clojure.main$repl.doInvoke (main.clj:368)
    clojure.lang.RestFn.invoke (RestFn.java:1523)
    nrepl.middleware.interruptible_eval$evaluate.invokeStatic (interruptible_eval.clj:84)
    nrepl.middleware.interruptible_eval$evaluate.invoke (interruptible_eval.clj:56)
    nrepl.middleware.interruptible_eval$interruptible_eval$fn__1298$fn__1302.invoke (interruptible_eval.clj:152)
    clojure.lang.AFn.run (AFn.java:22)
    nrepl.middleware.session$session_exec$main_loop__1368$fn__1372.invoke (session.clj:218)
    nrepl.middleware.session$session_exec$main_loop__1368.invoke (session.clj:217)
    clojure.lang.AFn.run (AFn.java:22)
    java.lang.Thread.run (Thread.java:829)

Ran 1 tests containing 1 assertions.
0 failures, 1 errors.
{:test 1, :pass 0, :fail 0, :error 1, :type :summary}
user=>

liquidz commented 1 year ago

@sheluchin vim-iced does not use clojure.test/run-tests directly, but uses cider-nrepl for testing. I checked the CIDER's behavior in Emacs and the problem is reproduced.

So it seems this is a bug in cider-nrepl.

sheluchin commented 1 year ago

Thank you, @liquidz. I've created this :point_up: issue in the cider-nrepl repo and made a reference to here in case anyone encounters this in the future. Please feel free to close this ticket if you like.

liquidz commented 1 year ago

@sheluchin I've bumped cider-nrepl to 0.28.6 in the latest vim-iced version, and it looks to solve this problem. Could you try the latest version?

sheluchin commented 1 year ago

@liquidz I can confirm that it works. Thanks as always!

liquidz / vim-iced

Exceptions thrown in tests cause an error #445