Clojure

Improve error printing in clojure.main with -m, -e, etc

Details

  • Type: Enhancement Enhancement
  • Status: Closed Closed
  • Priority: Critical Critical
  • Resolution: Completed
  • Affects Version/s: Release 1.10
  • Fix Version/s: Release 1.10.1
  • Component/s: None
  • Patch:
    Code
  • Approval:
    Ok

Description

Clojure 1.10 has a lot of improvements to print better errors in clojure.main when using the repl. However, these improvements do not extend to the default behavior when using other clojure.main modes like -m (run -main in a namespace), -e (run expression), or the script running option. All of these will simply let an exception throw out of the main and default to JVM behavior, which prints the stack of the full chain of exceptions.

Some practical ramifications of this are that anything in the ecosystem that is running Clojure programs via clojure.main (could be clj, but could also be other tools like "lein ring server" where I saw this happenn), these tools are not getting the advantages of the error improvements.

The general proposal is to catch Throwable around the call to the main entry point and at least run the Throwable->map, ex-triage, ex-str pipeline. Also need to consider what to do about printing the stack trace. The default JVM behavior is to print the stack of every exception in the chain, but printing either the root cause stack (in execution error) or no stack (in reader/compiler/macroexpansion cases) would likely be better.

Simple repro (note very long line of spec problem data that all gets spammed to the screen - have to scroll right to see it):

$ clj -e "(ns foo (import java.util.Date))"
Exception in thread "main" Syntax error macroexpanding clojure.core/ns at (1:1).
Call to clojure.core/ns did not conform to spec.
	at clojure.lang.Compiler.checkSpecs(Compiler.java:6971)
	at clojure.lang.Compiler.macroexpand1(Compiler.java:6987)
	at clojure.lang.Compiler.macroexpand(Compiler.java:7074)
	at clojure.lang.Compiler.eval(Compiler.java:7160)
	at clojure.lang.Compiler.eval(Compiler.java:7131)
	at clojure.core$eval.invokeStatic(core.clj:3214)
	at clojure.main$eval_opt.invokeStatic(main.clj:465)
	at clojure.main$eval_opt.invoke(main.clj:459)
	at clojure.main$initialize.invokeStatic(main.clj:485)
	at clojure.main$null_opt.invokeStatic(main.clj:519)
	at clojure.main$null_opt.invoke(main.clj:516)
	at clojure.main$main.invokeStatic(main.clj:598)
	at clojure.main$main.doInvoke(main.clj:561)
	at clojure.lang.RestFn.applyTo(RestFn.java:137)
	at clojure.lang.Var.applyTo(Var.java:705)
	at clojure.main.main(main.java:37)
Caused by: clojure.lang.ExceptionInfo: Call to clojure.core/ns did not conform to spec. {:clojure.spec.alpha/problems [{:path [], :reason "Extra input", :pred (clojure.spec.alpha/cat :docstring (clojure.spec.alpha/? clojure.core/string?) :attr-map (clojure.spec.alpha/? clojure.core/map?) :ns-clauses :clojure.core.specs.alpha/ns-clauses), :val ((import java.util.Date)), :via [:clojure.core.specs.alpha/ns-form], :in [1]}], :clojure.spec.alpha/spec #object[clojure.spec.alpha$regex_spec_impl$reify__2509 0x412c995d "clojure.spec.alpha$regex_spec_impl$reify__2509@412c995d"], :clojure.spec.alpha/value (foo (import java.util.Date)), :clojure.spec.alpha/args (foo (import java.util.Date))}
	at clojure.spec.alpha$macroexpand_check.invokeStatic(alpha.clj:705)
	at clojure.spec.alpha$macroexpand_check.invoke(alpha.clj:697)
	at clojure.lang.AFn.applyToHelper(AFn.java:156)
	at clojure.lang.AFn.applyTo(AFn.java:144)
	at clojure.lang.Var.applyTo(Var.java:705)
	at clojure.lang.Compiler.checkSpecs(Compiler.java:6969)
	... 15 more

As a macroexpansion spec error, this could just say:

$ clj -e "(ns foo (import java.util.Date))"
Syntax error macroexpanding clojure.core/ns at (1:1).
((import java.util.Date)) - failed: Extra input spec: :clojure.core.specs.alpha/ns-form

which would be much less scary.

Proposal: clojure.main is a process boundary. As such, the facilities for communicating information through it are limited to printing and the return value. Existing consumers of clojure.main are likely to be using the return value so that needs to be maintained. For the printing, we have expended a lot of energy to craft a good message for all phases in the 1.10 error message re-work, which is currently active at the repl. For other consumers of clojure.main, we wish to give them the same experience, but also want don't want to throw away the full exception chain / stack trace info for consumers that need it. In the repl, it's less critical to retain all info because further interactive calls can be made for pst or ex-data, but in a clojure.main exit, you're done.

As such, the attached patch saves all that information and puts it in a temp file (falling back to printing to stderr if the file can't be created) and prints just the error message you would get at the repl.

One additional change included in the patch is that the current ex-triage does not preserve and ex-str does not print the full path to the source file, just the file name itself. If the error is in, say core.clj, this is not helpful. So I've made an additive change there to also store the path and use it in the error message you see at both the REPL and in clojure.main.

For the example above, you'd see something like:

$ clj -e "(ns foo (import java.util.Date))"
Syntax error macroexpanding clojure.core/ns at (REPL:1:1).
((import java.util.Date)) - failed: Extra input spec: :clojure.core.specs.alpha/ns-form
Full report at: /var/folders/2k/2l7ch1xn7lb5gj86tgp1ygww0000gn/T/clojure-782738238888539988.edn

For an example with a namespace path:

$ clj -e "(require 'b.c)"
Syntax error (ArithmeticException) compiling at (b/c.clj:3:1).
Divide by zero
Full report at: /var/folders/2k/2l7ch1xn7lb5gj86tgp1ygww0000gn/T/clojure-8657942939058862044.edn

The temp file created is a readable .edn file which can be further processed by tooling if needed:

$ cat /var/folders/2k/2l7ch1xn7lb5gj86tgp1ygww0000gn/T/clojure-8657942939058862044.edn
{:clojure.main/message
 "Syntax error (ArithmeticException) compiling at (b/c.clj:3:1).\nDivide by zero\n",
 :clojure.main/triage
 {:clojure.error/phase :compile-syntax-check,
  :clojure.error/line 3,
  :clojure.error/column 1,
  :clojure.error/source "c.clj",
  :clojure.error/path "b/c.clj",
  :clojure.error/class java.lang.ArithmeticException,
  :clojure.error/cause "Divide by zero"},
 :clojure.main/trace
 {:via
  [{:type clojure.lang.Compiler$CompilerException,
    :message "Syntax error compiling at (b/c.clj:3:1).",
    :data
    {:clojure.error/phase :compile-syntax-check,
     :clojure.error/line 3,
     :clojure.error/column 1,
     :clojure.error/source "b/c.clj"},
    :at [clojure.lang.Compiler load "Compiler.java" 7647]}
   {:type java.lang.ArithmeticException,
    :message "Divide by zero",
    :at [clojure.lang.Numbers divide "Numbers.java" 188]}],
  :trace
  [[clojure.lang.Numbers divide "Numbers.java" 188]
   [clojure.lang.Numbers divide "Numbers.java" 3901]
   ...elided...
   [clojure.main main "main.java" 37]],
  :cause "Divide by zero",
  :phase :compile-syntax-check}}

Patch: clj-2463-5.patch

  1. clj-2463.patch
    04/Jan/19 2:17 PM
    1 kB
    Alex Miller
  2. clj-2463-2.patch
    26/Feb/19 4:25 PM
    7 kB
    Alex Miller
  3. clj-2463-3.patch
    27/Feb/19 11:18 AM
    7 kB
    Alex Miller
  4. clj-2463-4.patch
    01/Mar/19 11:18 AM
    9 kB
    Alex Miller
  5. clj-2463-5.patch
    20/Mar/19 10:24 AM
    9 kB
    Alex Miller

Activity

Hide
Alex Miller added a comment -

Attached a proof-of-concept hack at this. Needs more discussion about what to do about the stack traces, whether we can do a better job sharing code between clojure.main and clojure.repl/pst, and maybe should consider an option (like -x) to dump the full stack chain in case you need it for debugging.

Show
Alex Miller added a comment - Attached a proof-of-concept hack at this. Needs more discussion about what to do about the stack traces, whether we can do a better job sharing code between clojure.main and clojure.repl/pst, and maybe should consider an option (like -x) to dump the full stack chain in case you need it for debugging.
Hide
Stuart Halloway added a comment -

It is important to keep in mind all the ways that clojure.main is different from the REPL. When running the REPL, you still have the process after an exception happens. If you don't like the way exceptions are presented, you can programmatically grab the exception and do whatever your want. You can use the new 1.10 tools or write your own.

When clojure.main exits, your process is gone. If we make any change at all (particularly eliding detail for human reader convenience), and somebody wants something different, then they are out of luck. Also, printing the stack trace as Java does (the current behavior) means we are operationally compatible with production tooling designed around Java processes.

Most of the reported pain people feel from this would be fixed by making a tiny number of changes in how Java processes are launched from lein, boot, Cursive, et al. On the other side of such changes, these tools would have independent and full control of how users experience errors. They could match 1.10 behavior or enhance it, separate from the Clojure release cycle. And they could make different choices in different contexts.

Show
Stuart Halloway added a comment - It is important to keep in mind all the ways that clojure.main is different from the REPL. When running the REPL, you still have the process after an exception happens. If you don't like the way exceptions are presented, you can programmatically grab the exception and do whatever your want. You can use the new 1.10 tools or write your own. When clojure.main exits, your process is gone. If we make any change at all (particularly eliding detail for human reader convenience), and somebody wants something different, then they are out of luck. Also, printing the stack trace as Java does (the current behavior) means we are operationally compatible with production tooling designed around Java processes. Most of the reported pain people feel from this would be fixed by making a tiny number of changes in how Java processes are launched from lein, boot, Cursive, et al. On the other side of such changes, these tools would have independent and full control of how users experience errors. They could match 1.10 behavior or enhance it, separate from the Clojure release cycle. And they could make different choices in different contexts.
Hide
Alex Miller added a comment -

Ideally, there should be both a programmatic entry point and a command line wrapper entry point that prints rather than leaves it to the jvm.

Show
Alex Miller added a comment - Ideally, there should be both a programmatic entry point and a command line wrapper entry point that prints rather than leaves it to the jvm.
Hide
Alex Miller added a comment -

Added updated -3 patch

Show
Alex Miller added a comment - Added updated -3 patch
Hide
Alex Miller added a comment - - edited

Because leiningen relies on forking commands as a clojure.main process in many cases, this will also affect leiningen output. Example (annotated left column notes who is printing):

$ lein compile
LEIN  Compiling err.core
LEIN  Syntax error compiling at (err/core.clj:5:1).
CLJ   Syntax error compiling at (err/core.clj:5:1).
CLJ   Unable to resolve symbol: defnfoo in this context
CLJ   Full report at: /var/folders/2k/2l7ch1xn7lb5gj86tgp1ygww0000gn/T/clojure-12258630339337634263.edn
LEIN  Compilation failed: Subprocess failed

The double "Syntax error compiling" line is because Leiningen is printing in addition to clojure.main. Leiningen could take more control over what happens here if desired. Relevant code: https://github.com/technomancy/leiningen/blob/ba9d2ac9920e6622c944fcf223debbeadf85222d/src/leiningen/compile.clj#L150-L171

Show
Alex Miller added a comment - - edited Because leiningen relies on forking commands as a clojure.main process in many cases, this will also affect leiningen output. Example (annotated left column notes who is printing):
$ lein compile
LEIN  Compiling err.core
LEIN  Syntax error compiling at (err/core.clj:5:1).
CLJ   Syntax error compiling at (err/core.clj:5:1).
CLJ   Unable to resolve symbol: defnfoo in this context
CLJ   Full report at: /var/folders/2k/2l7ch1xn7lb5gj86tgp1ygww0000gn/T/clojure-12258630339337634263.edn
LEIN  Compilation failed: Subprocess failed
The double "Syntax error compiling" line is because Leiningen is printing in addition to clojure.main. Leiningen could take more control over what happens here if desired. Relevant code: https://github.com/technomancy/leiningen/blob/ba9d2ac9920e6622c944fcf223debbeadf85222d/src/leiningen/compile.clj#L150-L171
Hide
Alex Miller added a comment -

-4 patch adds explicit clojure.main option --report-stderr to force reporting to stderr

Show
Alex Miller added a comment - -4 patch adds explicit clojure.main option --report-stderr to force reporting to stderr
Hide
Alex Miller added a comment -

-5 patch reworks the error reporting stuff away from a private macro and into a public function that can be reused with flags for reporting target and system/exit.

Show
Alex Miller added a comment - -5 patch reworks the error reporting stuff away from a private macro and into a public function that can be reused with flags for reporting target and system/exit.

People

Vote (2)
Watch (6)

Dates

  • Created:
    Updated:
    Resolved: