Cider: Cider error handling broken by Clojure 1.10.0-alpha7

Created on 7 Sep 2018  路  25Comments  路  Source: clojure-emacs/cider

Expected behavior

When trying to evaluate a form with an error at compile time, or instance evaling a symbol that wasn't def'd, a *cider-error* buffer should pop up with a message like:

Unable to resolve symbol: foo in this context

This is working on all clojure versions up to and including 1.10.0-alpha6

Actual behavior

On the newly released 1.10.0-alpha7 no *cider-error* buffer appears and this stacktrace is printed to the repl buffer:

Syntax error compiling at (/home/adam/.../file.clj:1:14953).
Cause: Unable to resolve symbol: foo in this context
08:47:37 ERROR -agent-send-off-pool-6 c.t.n.server                        Unhandled REPL handler exception processing message {:op stacktrace, :pprint-fn clojure.pprint/pprint, :print-length 50, :print-level 50, :session 1ce5fdb6-4ef6-41d5-93d8-3726abae8cbe, :id 42}
java.lang.NullPointerException: null
    at clojure.string$replace_first.invokeStatic(string.clj:165)
    at clojure.string$replace_first.invoke(string.clj:138)
    at cider.nrepl.middleware.stacktrace$relative_path.invokeStatic(stacktrace.clj:204)
    at cider.nrepl.middleware.stacktrace$relative_path.invoke(stacktrace.clj:198)
    at cider.nrepl.middleware.stacktrace$extract_location.invokeStatic(stacktrace.clj:219)
    at cider.nrepl.middleware.stacktrace$extract_location.invoke(stacktrace.clj:206)
    at clojure.core$comp$fn__5628.invoke(core.clj:2561)
    at clojure.core$map$fn__5686.invoke(core.clj:2747)
    at clojure.lang.LazySeq.sval(LazySeq.java:42)
    at clojure.lang.LazySeq.seq(LazySeq.java:51)
    at clojure.lang.RT.seq(RT.java:528)
    at clojure.core$seq__5223.invokeStatic(core.clj:137)
    at clojure.core$seq__5223.invoke(core.clj:137)
    at cider.nrepl.middleware.stacktrace$handle_stacktrace.invokeStatic(stacktrace.clj:312)
    at cider.nrepl.middleware.stacktrace$handle_stacktrace.invoke(stacktrace.clj:309)

Looking at clojure's changelog, I believe it's likely that CLJ-2386 was the culprit for the breaking change.

Steps to reproduce the problem

Eval a symbol foo in an otherwise blank clojure buffer while running clojure 1.10.0-alpha7

CIDER version information

Include here the version string displayed when
CIDER's REPL is launched. Here's an example:

;; CIDER 0.18.0snapshot (package: 20180806.1933), nREPL 0.2.13
;; Clojure 1.10.0-alpha7, Java 1.8.0_181

Emacs version

27.0.50

Operating system

Linux

bug good first issue stale

Most helpful comment

The error messaging being parsed in 10 alpha 7 is

Syntax error compiling at (cider-repl clojure/simplematch:localhost:35829(clj):43:7).

vs 1.9

java.lang.RuntimeException: Unable to resolve symbol: x in this context, compiling:(cider-repl clojure/simplematch:localhost:33029(clj):43:7)

The parsing is:

(re-find #"(.*?), compiling:\((.*):(\d+):(\d+)\)" message) which on the clojure 1.9 message yields

["java.lang.RuntimeException: Unable to resolve symbol: x in this context, compiling:(*cider-repl clojure/simplematch:localhost:33029(clj)*:43:7)" "java.lang.RuntimeException: Unable to resolve symbol: x in this context" "*cider-repl clojure/simplematch:localhost:33029(clj)*" "43" "7"]

and is nil on the 1.10 message.

All 25 comments

The error messaging being parsed in 10 alpha 7 is

Syntax error compiling at (cider-repl clojure/simplematch:localhost:35829(clj):43:7).

vs 1.9

java.lang.RuntimeException: Unable to resolve symbol: x in this context, compiling:(cider-repl clojure/simplematch:localhost:33029(clj):43:7)

The parsing is:

(re-find #"(.*?), compiling:\((.*):(\d+):(\d+)\)" message) which on the clojure 1.9 message yields

["java.lang.RuntimeException: Unable to resolve symbol: x in this context, compiling:(*cider-repl clojure/simplematch:localhost:33029(clj)*:43:7)" "java.lang.RuntimeException: Unable to resolve symbol: x in this context" "*cider-repl clojure/simplematch:localhost:33029(clj)*" "43" "7"]

and is nil on the 1.10 message.

Unless I'm missing something, in this case it seems that some valuable information is now missing from the error message. I'm fine with changing CIDER to support the new format, but I really want us to have some meaningful errors we can parse for our users.

Let's also ping @puredanger for input.

We've changed the root exception message in a number of cases (CLJ-2373 is the primary change). The important messages all still exist (although they may exist in different nested parts of the throwable chain. In this case you probably have a CompilerException wrapping an ExceptionInfo, which is a spec exception. The clojure.main repl is now doing more work to assemble parts of the exception chain into a more meaningful experience for a repl user based on the chain. Other tools (such as CIDER) can do the same. Some of this is exposed in clojure.main/ex-str (in 1.10.0-alpha7) but you can replicate what's happening there in whatever way you want in the CIDER repl.

I guess I should also mention that CompilerExceptions (as of 1.10.0-alpha7) also have ex-info data so you can use ex-data to extract data like error phase, file, line, column, symbol, etc.

Thanks for the input, Alex! I think currently we just do some textual processing of the messages to make them clickable in the REPL, but I guess we can potentially expand on the checks to recover and display the important information.

I think the new compiler exception ex-data, wrapping for macroexpansion cases, and moving away from burying data in strings is a substantially better place to be for tools. That said, that's you, so I'm interested in feedback as you move into using it.

Here's an example. This is a compiler error and you will get a CompilerException wrapping a RuntimeException (that's all the same as all previous releases). The difference is that the CompilerException now supports ex-data and you can get to all the bits of important data as data. It's also doing less string building in the message of the root exception, however you can see that the messages are in the top and bottom messages of the chain. You can actually get a combined message by calling .toString() on the root too:

```Clojure 1.10.0-master-SNAPSHOT
user=> foo
Syntax error compiling at (0:0).
Cause: Unable to resolve symbol: foo in this context
user=> (ex-data *e)

:clojure.error{:line 0, :column 0, :phase :compile, :source "NO_SOURCE_PATH"}

user=> (.toString *e)
"Syntax error compiling at (0:0).\nCause: Unable to resolve symbol: foo in this context"
user=> *e

error {

:cause "Unable to resolve symbol: foo in this context"
:via
[{:type clojure.lang.Compiler$CompilerException
:message "Syntax error compiling at (0:0)."
:data #:clojure.error{:line 0, :column 0, :phase :compile, :source "NO_SOURCE_PATH"}
:at [clojure.lang.Compiler analyze "Compiler.java" 6799]}
{:type java.lang.RuntimeException
:message "Unable to resolve symbol: foo in this context"
:at [clojure.lang.Util runtimeException "Util.java" 221]}]
:trace
[[clojure.lang.Util runtimeException "Util.java" 221]
[clojure.lang.Compiler resolveIn "Compiler.java" 7397]
[clojure.lang.Compiler resolve "Compiler.java" 7341]
[clojure.lang.Compiler analyzeSymbol "Compiler.java" 7302]
[clojure.lang.Compiler analyze "Compiler.java" 6759]
[clojure.lang.Compiler analyze "Compiler.java" 6736]
[clojure.lang.Compiler eval "Compiler.java" 7164]
[clojure.lang.Compiler eval "Compiler.java" 7123]
[clojure.core$eval invokeStatic "core.clj" 3206]
[clojure.core$eval invoke "core.clj" 3202]
[clojure.main$repl$read_eval_print__8766$fn__8769 invoke "main.clj" 299]
[clojure.main$repl$read_eval_print__8766 invoke "main.clj" 299]
[clojure.main$repl$fn__8775 invoke "main.clj" 322]
[clojure.main$repl invokeStatic "main.clj" 322]
[clojure.main$repl_opt invokeStatic "main.clj" 386]
[clojure.main$main invokeStatic "main.clj" 485]
[clojure.main$main doInvoke "main.clj" 448]
[clojure.lang.RestFn invoke "RestFn.java" 397]
[clojure.lang.AFn applyToHelper "AFn.java" 152]
[clojure.lang.RestFn applyTo "RestFn.java" 132]
[clojure.lang.Var applyTo "Var.java" 705]
[clojure.main main "main.java" 37]]}```

I think the new compiler exception ex-data, wrapping for macroexpansion cases, and moving away from burying data in strings is a substantially better place to be for tools. That said, that's you, so I'm interested in feedback as you move into using it.

Sure. Btw, is there any special reason for punctuation/language used in:

Syntax error compiling at (0:0).
Cause: Unable to resolve symbol: foo in this context

Seems to me it'd be nice if (0:0) is updated to something like (REPL:0:0) for consistency with errors originating in files. I'd also love to be able to read the second line easier. E.g.:

Cause: Unable to resolve symbol `foo` in this context.

(I'm surprised about the : and the fact the second message doesn't end with a ..) Maybe NO_SOURCE_PATH can also be replaced with the more descriptive REPL?

First line format is generally:
"Syntax error compiling at (0:0)." == "<error-type> <phase>ing at <location>."

The location has been using (SOURCE:LINE:COL) for a long time to report Clojure source errors. We are now omitting the first part when at the repl (you'll still see the source referring to a Clojure file if it's coming from a file). In general, I'd rather say nothing than something that is the same in every error, which has no informational value. If anything, you could argue the line and column info here are probably not even useful (as "line" is actually the nth repl invocation). The CompilerException message is only a descriptive wrapper about the circumstances in which the error was caught so you are welcome to make your own message out of the pieces provided in the ex-info data! That is, when a CompilerException is constructed, it has no message of its own - the message is just a template constructed from the other ex data, which you have.

The second line is of the form "Cause: <root-cause-message>". The quotes and absence of a final period are coming from a hard-coded message in the compiler, not the generic stuff that we changed. In general, the Compiler does not either end messages in periods or quote symbols across the 100s of messages in the Compiler (or others in explicit macro checks), so I will infer that that is Rich's stylistic preference.

Thanks for the detailed explanations, Alex!

I'd rather say nothing than something that is the same in every error, which has no informational value. If anything, you could argue the line and column info here are probably not even useful (as "line" is actually the nth repl invocation).

I don't quite get this. Are they actually the line and column relative to the current prompt? This is certainly very useful information if you're working on a rich REPL.

The quotes and absence of a final period are coming from a hard-coded message in the compiler, not the generic stuff that we changed. In general, the Compiler does not either end messages in periods or quote symbols across the 100s of messages in the Compiler (or others in explicit macro checks), so I will infer that that is Rich's stylistic preference.

Got it. Could you discuss with him if he's open to changing those? I don't care that much about the punctuation being ideal, but I feel it'd be nice if at least symbol references stood out more in error messages.

FWIW I think this is a great addition for tooling

user=> (ex-data *e)
#:clojure.error{:line 0, :column 0, :phase :compile, :source "NO_SOURCE_PATH"}

It is, but we have to think how exactly to implement this. You can not just call ex-data in the primary REPL - I mean you can, but this will mess up *1, etc. You can't also do this in the tooling session, because there won't be any *e. Likely by default we'll just to tune the regexp that parses the error and stuff the rest of the handling in a middleware.

I guess it'd be simplest to just tune (re-find #"(.*?), compiling:\((.*):(\d+):(\d+)\)" message) to take into account compiling at and leave the advanced processing for down the road.

It would be interesting to know if this was solved by
https://github.com/clojure-emacs/cider-nrepl/pull/551

@slipset You and me both. Can you test this?

WIth

[nREPL] Starting server via /usr/local/bin/clojure -Sdeps '{:deps {nrepl {:mvn/version "0.4.5"} refactor-nrepl {:mvn/version "2.4.0"} cider/cider-nrepl {:mvn/version "0.19.0-SNAPSHOT"}}}' -e '(require (quote cider-nrepl.main)) (cider-nrepl.main/init ["refactor-nrepl.middleware/wrap-refactor", "cider.nrepl/cider-middleware"])'

I see

user> foo
Syntax error compiling at (*cider-repl github.com/speculative:localhost:54899(clj)*:1:36).
Unable to resolve symbol: foo in this context
user> *clojure-version*
;; => {:major 1, :minor 10, :incremental 0, :qualifier "RC1"}
user> 

I think you need to do some interactive eval to see if the error highlighting and the stacktrace buffer look OK.

Hmm,
The ticket says

Eval a symbol foo in an otherwise blank clojure buffer while running clojure 1.10.0-alpha7

is enough to repro the problem.

But here is some more evaluated stuff:
user> *clojure-version* ;; => {:major 1, :minor 10, :incremental 0, :qualifier "RC1"} user> (defn l) Syntax error macroexpanding clojure.core/defn at (*cider-repl github.com/speculative:localhost:54899(clj)*:48:7). () - failed: Insufficient input at: [:fn-tail] spec: :clojure.core.specs.alpha/defn-args user> (let [1]) Syntax error macroexpanding clojure.core/let at (*cider-repl github.com/speculative:localhost:54899(clj)*:51:7). [1] - failed: even-number-of-forms? at: [:bindings] spec: :clojure.core.specs.alpha/bindings user> (/ 0) Evaluation error (ArithmeticException) at clojure.lang.Numbers.divide (Numbers.java:188). Divide by zero user> (require) Syntax error compiling at (*cider-repl github.com/speculative:localhost:54899(clj)*:57:7). Nothing specified to load Syntax error macroexpanding clojure.core/let at (/Users/erik/Documents/github.com/speculative/src/speculative/core.cljc:5:1). [1] - failed: even-number-of-forms? at: [:bindings] spec: :clojure.core.specs.alpha/bindings Syntax error macroexpanding clojure.core/let at (/Users/erik/Documents/github.com/speculative/src/speculative/core.cljc:5:1). [1] - failed: even-number-of-forms? at: [:bindings] spec: :clojure.core.specs.alpha/bindings user>

Let me know if there are specific things you'd want me to test.

Eval a symbol foo in an otherwise blank clojure buffer while running clojure 1.10.0-alpha7

Source buffer. :-) The problem is that because of the changed format of the error messages they were not properly parsed and the cider-error buffer would not work. REPL evaluations don't trigger the stacktrace buffer.

screenshot 2018-10-31 at 20 40 20

FYI, there will be some additional changes coming in https://dev.clojure.org/jira/browse/CLJ-2420 for the next 1.10 pre-release (not sure if they affect the current code as well).

Having the same error with:

*clojure-version*
{:major 1, :minor 10, :incremental 0, :qualifier "beta3"}

looks like it happens because source location not set with clojure.error/source anymore, but I found that it now could be found in (@session #'*file*) (see https://github.com/clojure-emacs/cider-nrepl/blob/7d2ed83b3a57f3883f4a9edd7f6cf83a8d0888b0/src/cider/nrepl/middleware/stacktrace.clj#L321).

I see also that extract-location tries to parse it from message. But in my case message doesn't contain it also.

I'll try to add info from *file* but not sure if it makes sense or not

Now that 1.10 is out, I am hoping this can get sorted out? (I know, jump in and do it myself, but I am already sacrificing sleep for my own free open-source projects, I don鈥檛 have the spare cycles! 馃槀 )

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contribution and understanding!

This issues been automatically closed due to lack of activity. Feel free to re-open it if you ever come back to it.

Was this page helpful?
0 / 5 - 0 ratings