Uploaded image for project: 'Clojure'
  1. CLJ-2463

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

    Details

    • Approval:
      Ok
    • Patch:
      Code

      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

        Attachments

        1. clj-2463.patch
          1 kB
        2. clj-2463-2.patch
          7 kB
        3. clj-2463-3.patch
          7 kB
        4. clj-2463-4.patch
          9 kB
        5. clj-2463-5.patch
          9 kB

          Activity

            People

            • Assignee:
              Unassigned
              Reporter:
              alexmiller Alex Miller
            • Votes:
              1 Vote for this issue
              Watchers:
              5 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved: