feat: first steps for better error reporting (#140)

java-src/io/github/erdos/stencil/exceptions/EvalException.java

@@ -5,15 +5,15 @@
  */
 public final class EvalException extends RuntimeException {
 
+ public EvalException(String message, Exception cause) {
+ super(message, cause);
+ }
+
  private EvalException(Exception cause) {
  super(cause);
  }
 
  private EvalException(String message) {
  super(message);
  }
-
- public static EvalException wrapping(Exception cause) {
- return new EvalException(cause);
- }
 }

java-src/io/github/erdos/stencil/impl/NativeEvaluator.java

@@ -55,8 +55,10 @@ public EvaluatedDocument render(PreparedTemplate template, Map<String, PreparedF
  final Map result;
  try {
  result = (Map) fn.invoke(argsMap);
+ } catch (EvalException e) {
+ throw e;
  } catch (Exception e) {
- throw EvalException.wrapping(e);
+ throw new EvalException("Unexpected error", e);
  }
 
  final Consumer<OutputStream> stream = resultWriter(result);

service/src/stencil/service.clj

@@ -63,6 +63,9 @@
  (prepared template)
  (throw (ex-info "Template file does not exist!" {:status 404})))))
 
+(defn- exception->str [e]
+ (clojure.string/join "\n" (for [e (iterate #(.getCause %) e) :while e] (.getMessage e))))
+
 (defn wrap-err [handler]
  (fn [request]
  (try (handler request)
@@ -72,7 +75,10 @@
  {:status status
  :body (str "ERROR: " (.getMessage e))})
  (do (log/error "Error" e)
- (throw e)))))))
+ (throw e))))
+ (catch Exception e
+ {:status 400
+ :body (exception->str e)}))))
 
 (defn- wrap-log [handler]
  (fn [req]

src/stencil/cleanup.clj

@@ -24,8 +24,8 @@
 
  :else-if
  (if (empty? ss0)
- (throw (parsing-exception (str open-tag "else" close-tag)
- "Unexpected {%else%} tag, it must come right after a condition!"))
+ (throw (parsing-exception (str open-tag "else if" close-tag)
+ "Unexpected {%else if%} tag, it must come right after a condition!"))
  (-> ss0
  (mod-stack-top-last update ::blocks (fnil conj []) {::children queue})
  (conj [(assoc token :cmd :if :r true)])

src/stencil/eval.clj

@@ -4,6 +4,7 @@
  [stencil.infix :refer [eval-rpn]]
  [stencil.types :refer [control?]]
  [stencil.tokenizer :as tokenizer]
+ [stencil.util :refer [eval-exception]]
  [stencil.tree-postprocess :as tree-postprocess]))
 
 (set! *warn-on-reflection* true)
@@ -18,19 +19,24 @@
  (assert (or (nil? items) (sequential? items)))
  (eduction (mapcat (partial eval-step function data)) items))
 
+(defn- eval-rpn* [data function expr raw-expr]
+ (try (eval-rpn data function expr)
+ (catch Exception e
+ (throw (eval-exception (str "Error evaluating expression: " raw-expr) e)))))
+
 (defmethod eval-step :if [function data item]
- (let [condition (eval-rpn data function (:condition item))]
+ (let [condition (eval-rpn* data function (:condition item) (:raw item))]
  (log/trace "Condition {} evaluated to {}" (:condition item) condition)
  (->> (if condition (:then item) (:else item))
  (normal-control-ast->evaled-seq data function))))
 
 (defmethod eval-step :echo [function data item]
- (let [value (eval-rpn data function (:expression item))]
+ (let [value (eval-rpn* data function (:expression item) (:raw item))]
  (log/trace "Echoing {} as {}" (:expression item) value)
  [{:text (if (control? value) value (str value))}]))
 
 (defmethod eval-step :for [function data item]
- (let [items (eval-rpn data function (:expression item))]
+ (let [items (eval-rpn* data function (:expression item) (:raw item))]
  (log/trace "Loop on {} will repeat {} times" (:expression item) (count items))
  (if (not-empty items)
  (let [index-var-name (name (:index-var item))

src/stencil/infix.clj

@@ -153,10 +153,10 @@
 ;; throws ExceptionInfo when token sequence has invalid elems
 (defn- validate-tokens [tokens]
  (cond
- (some true? (map #(and (or (symbol? %1) (number? %1) (#{:close} %1))
- (or (symbol? %2) (number? %2) (#{:open} %2)))
+ (some true? (map #(and (or (symbol? %1) (number? %1) (= :close %1))
+ (or (symbol? %2) (number? %2) (= :open %2)))
  tokens (next tokens)))
- (throw (ex-info "Could not parse!" {}))
+ (throw (ex-info "Invalid stencil expression!" {}))
 
  :else
  tokens))
@@ -280,8 +280,8 @@
  (log/trace "Result was {}" result)
  (conj new-stack result))
  (catch clojure.lang.ArityException e
- (throw (ex-info (str "Wrong arity: " (.getMessage e))
- {:fn fn :expected args :got (count ops) :ops (vec ops)})))))
+ (throw (ex-info (format "Function '%s' was called with a wrong number of arguments (%d)" fn args)
+ {:fn fn :got args})))))
 
 (defmacro def-reduce-step [cmd args body]
  (assert (keyword? cmd))

src/stencil/merger.clj

@@ -6,7 +6,7 @@
  [stencil
  [types :refer [open-tag close-tag]]
  [tokenizer :as tokenizer]
- [util :refer [prefixes suffixes subs-last string]]]))
+ [util :refer [prefixes suffixes subs-last string parsing-exception]]]))
 
 (set! *warn-on-reflection* true)
 
@@ -75,7 +75,8 @@
 
 (defn map-action-token [token]
  (if-let [action (:action token)]
- (let [parsed (tokenizer/text->cmd action)]
+ (let [parsed (tokenizer/text->cmd action)
+ parsed (assoc parsed :raw (str open-tag action close-tag))]
  (if (and *only-includes*
  (not= :cmd/include (:cmd parsed)))
  {:text (str open-tag action close-tag)}
@@ -95,7 +96,9 @@
  (take (count close-tag) (map :char %)))
  (suffixes (peek-next-text next-token-list)))
  that (if (empty? that)
- (throw (ex-info "Tag is not closed? " {:read (first this)}))
+ (throw (parsing-exception "" (str "Stencil tag is not closed. Reading " open-tag
+ (string (comp (take 20) (map first) (map :char)) this))))
+ ;; (throw (ex-info "Tag is not closed? " {:read (first this)}))
  (first (nth that (dec (count close-tag)))))
  ; action-content (apply str (map (comp :char first) this))
  ]

src/stencil/model.clj

@@ -10,7 +10,7 @@
  [stencil.model.numbering :as numbering]
  [stencil.types :refer [->FragmentInvoke ->ReplaceImage]]
  [stencil.postprocess.images :refer [img-data->extrafile]]
- [stencil.util :refer [unlazy-tree assoc-if-val]]
+ [stencil.util :refer [unlazy-tree assoc-if-val eval-exception]]
  [stencil.model.relations :as relations]
  [stencil.model.common :refer [unix-path ->xml-writer resource-copier]]
  [stencil.functions :refer [call-fn]]
@@ -254,9 +254,7 @@
  (swap! *inserted-fragments* conj frag-name)
  (run! add-extra-file! relation-ids-rename)
  [{:text (->FragmentInvoke {:frag-evaled-parts evaled-parts})}])
- (throw (ex-info "Did not find fragment for name!"
- {:fragment-name frag-name
- :all-fragment-names (set (keys *all-fragments*))})))))
+ (throw (eval-exception (str "No fragment for name: " frag-name) nil)))))
 
 
 ;; replaces the nearest image with the content

src/stencil/tokenizer.clj

@@ -47,12 +47,12 @@
  {:cmd :else-if
  :condition (infix/parse (.substring text prefix-len))})
 
- :else (throw (ex-info "Unexpected command" {:command text})))))
+ :else (throw (ex-info (str "Unexpected command: " text) {})))))
 
 (defn text->cmd [text]
  (try (text->cmd-impl text)
- (catch clojure.lang.ExceptionInfo e
- (throw (parsing-exception (str open-tag text close-tag) (.getMessage e))))))
+  (catch clojure.lang.ExceptionInfo e
+  (throw (parsing-exception text (.getMessage e))))))
 
 (defn structure->seq [parsed]
  (cond

src/stencil/util.clj

@@ -1,6 +1,6 @@
 (ns stencil.util
  (:require [clojure.zip])
- (:import [io.github.erdos.stencil.exceptions ParsingException]))
+ (:import [io.github.erdos.stencil.exceptions ParsingException EvalException]))
 
 (set! *warn-on-reflection* true)
 
@@ -71,6 +71,10 @@
 (defn parsing-exception [expression message]
  (ParsingException/fromMessage (str expression) (str message)))
 
+(defn eval-exception [message expression]
+ (assert (string? message))
+ (EvalException. message expression))
+
 ;; return xml zipper of location that matches predicate or nil
 (defn find-first-in-tree [predicate tree-loc]
  (assert (ifn? predicate))

test/stencil/errors.clj

@@ -1,6 +1,7 @@
 (ns stencil.errors
- (:import [io.github.erdos.stencil.exceptions ParsingException])
+ (:import [io.github.erdos.stencil.exceptions ParsingException EvalException])
  (:require [stencil.types :refer :all]
+ [stencil.integration :refer [test-fails]]
  [clojure.test :refer [deftest is are testing]]
  [stencil.model :as model]))
 
@@ -9,10 +10,6 @@
  (->> xml-str (str) (.getBytes) (new java.io.ByteArrayInputStream) (model/->exec)))
 
 
-(defmacro ^:private throw-ex-info? [expr]
- `(is (~'thrown? clojure.lang.ExceptionInfo (test-prepare ~expr))))
-
-
 (defmacro ^:private throw-ex-parsing? [expr]
  `(is (~'thrown? ParsingException (test-prepare ~expr))))
 
@@ -54,12 +51,67 @@
 
 (deftest test-not-closed
  (testing "Expressions are not closed properly"
- (throw-ex-info? "<a>{%=</a>")
- (throw-ex-info? "<a>{%=x</a>")
- (throw-ex-info? "<a>{%=x%</a>")
- (throw-ex-info? "<a>{%=x}</a>"))
+ (throw-ex-parsing? "<a>{%=</a>")
+ (throw-ex-parsing? "<a>{%=x</a>")
+ (throw-ex-parsing? "<a>{%=x%</a>")
+ (throw-ex-parsing? "<a>{%=x}</a>"))
  (testing "Middle expr is not closed"
  (throw-ex-parsing? "<a><b>{%=1%}</b>{%=3<c>{%=4%}</c></a>")))
 
+
 (deftest test-unexpected-cmd
  (throw-ex-parsing? "<a>{% echo 3 %}</a>"))
+
+;; integration tests
+
+(deftest test-parsing-errors
+ (testing "Closing tag is missing"
+ (test-fails "test-resources/failures/test-syntax-nonclosed.docx" nil
+ ParsingException "Missing {%end%} tag from document!"))
+ (testing "Extra closing tag is present"
+ (test-fails "test-resources/failures/test-syntax-closed.docx" nil
+ ParsingException "Too many {%end%} tags!"))
+ (testing "A tag not closed until the end of document"
+ (test-fails "test-resources/failures/test-syntax-incomplete.docx" nil
+ ParsingException "Stencil tag is not closed. Reading {% if x + y"))
+ (testing "Unexpected {%else%} tag"
+ (test-fails "test-resources/failures/test-syntax-unexpected-else.docx" nil
+ ParsingException "Unexpected {%else%} tag, it must come right after a condition!"))
+ (testing "Unexpected {%else if%} tag"
+ (test-fails "test-resources/failures/test-syntax-unexpected-elif.docx" nil
+ ParsingException "Unexpected {%else if%} tag, it must come right after a condition!"))
+ (testing "Cannot parse infix expression"
+ (test-fails "test-resources/failures/test-syntax-fails.docx" nil
+ ParsingException "Invalid stencil expression!"))
+ (testing "Test unexpected command"
+ (test-fails "test-resources/failures/test-syntax-unexpected-command.docx" nil
+ ParsingException "Unexpected command: unexpected")))
+
+(deftest test-evaluation-errors
+ (testing "Division by zero"
+ (test-fails "test-resources/failures/test-eval-division.docx" {:x 1 :y 0}
+ EvalException "Error evaluating expression: {%=x/y%}"
+ java.lang.ArithmeticException "Divide by zero"))
+ (testing "NPE"
+ (test-fails "test-resources/failures/test-eval-division.docx" {:x nil :y nil}
+ EvalException "Error evaluating expression: {%=x/y%}"
+ java.lang.NullPointerException nil #_"Cannot invoke \"Object.getClass()\" because \"x\" is null"))
+ (testing "function does not exist"
+ (test-fails "test-resources/failures/test-no-such-fn.docx" {}
+ EvalException "Error evaluating expression: {%=nofun()%}"
+ java.lang.IllegalArgumentException "Did not find function for name nofun"))
+ (testing "function invoked with wrong arity"
+ (test-fails "test-resources/failures/test-syntax-arity.docx" {}
+ EvalException "Error evaluating expression: {%=decimal(1,2,3)%}"
+ clojure.lang.ExceptionInfo "Function 'decimal' was called with a wrong number of arguments (3)"))
+ (testing "Missing fragment"
+ (test-fails "test-resources/multipart/main.docx" {}
+ EvalException "No fragment for name: body"))
+ (testing "date() function has custom message"
+ (test-fails "test-resources/test-function-date.docx" {"date" "2022-01-04XXX11:22:33"}
+ EvalException "Error evaluating expression: {%=date(\"yyyy-MM-dd\", date)%}"
+ IllegalArgumentException "Could not parse date object 2022-01-04XXX11:22:33"))
+
+ (testing "function invocation error"
+ ;; TODO: invoke fn with wrong types
+ ))

test/stencil/integration.clj

@@ -1,6 +1,7 @@
 (ns stencil.integration
  "Integration test helpers"
  (:require [clojure.zip :as zip]
+ [clojure.test :refer [do-report is]]
  [stencil.api :as api]))
 
 
@@ -23,3 +24,25 @@
  :when (= stencil.ooxml/t (:tag (zip/node node)))
  c (:content (zip/node node))]
  c)))))
+
+
+(defn test-fails
+ "Tests that rendering the template with the payload results in the given exception chain."
+ [template payload & bodies]
+ (assert (string? template))
+ (assert (not-empty bodies))
+ (try (with-open [template (api/prepare template)]
+ (api/render! template payload
+ :overwrite? true
+ :output (java.io.File/createTempFile "stencil" ".docx")))
+ (do-report {:type :error
+ :message "Should have thrown exception"
+ :expected (first bodies)
+ :actual nil})
+ (catch RuntimeException e
+ (let [e (reduce (fn [e [t reason]]
+ (is (instance? t e))
+ (or (= t NullPointerException) (is (= reason (.getMessage e))))
+ (.getCause e))
+ e (partition 2 bodies))]
+ (is (= nil e) "Cause must be null.")))))

test/stencil/merger_test.clj

@@ -106,29 +106,29 @@
 
  [{:text "{%=1%}"}]
  [{:text "{%=1%}"}]
- [{:action {:cmd :echo, :expression [1]}}]
+ [{:action {:cmd :echo, :expression [1] :raw "{%=1%}"}}]
 
  [{:text "abc{%=1%}b"}]
  [{:text "abc"} {:text "{%=1%}"} {:text "b"}]
- [{:text "abc"} {:action {:cmd :echo, :expression [1]}} {:text "b"}]
+ [{:text "abc"} {:action {:cmd :echo, :expression [1] :raw "{%=1%}"}} {:text "b"}]
 
  [{:text "abc{%="} O1 O2 {:text "1"} O3 O4 {:text "%}b"}]
  [{:text "abc"} {:text "{%="} O1 O2 {:text "1"} O3 O4 {:text "%}b"}]
- [{:text "abc"} {:action {:cmd :echo, :expression [1]}} O1 O2 O3 O4 {:text "b"}]
+ [{:text "abc"} {:action {:cmd :echo, :expression [1] :raw "{%=1%}"}} O1 O2 O3 O4 {:text "b"}]
 
  [{:text "abc{%="} O1 O2 {:text "1%"} O3 O4 {:text "}b"}]
  [{:text "abc"} {:text "{%="} O1 O2 {:text "1%"} O3 O4 {:text "}b"}]
- [{:text "abc"} {:action {:cmd :echo, :expression [1]}} O1 O2 O3 O4 {:text "b"}]
+ [{:text "abc"} {:action {:cmd :echo, :expression [1] :raw "{%=1%}"}} O1 O2 O3 O4 {:text "b"}]
 
  [{:text "abcd{%="} O1 {:text "1"} O2 {:text "%"} O3 {:text "}"} O4 {:text "b"}]
  [{:text "abcd"} {:text "{%="} O1 {:text "1"} O2 {:text "%"} O3 {:text "}"} O4 {:text "b"}]
- [{:text "abcd"} {:action {:cmd :echo, :expression [1]}} O1 O2 O3 O4{:text "b"}]
+ [{:text "abcd"} {:action {:cmd :echo, :expression [1] :raw "{%=1%}"}} O1 O2 O3 O4{:text "b"}]
 
  [{:text "abc{"} O1 {:text "%"} O2 {:text "=1"} O3 {:text "2"} O4 {:text "%"} O5 {:text "}"} {:text "b"}]
  [{:text "abc"} {:text "{"} O1 {:text "%"} O2 {:text "=1"} O3 {:text "2"} O4 {:text "%"} O5 {:text "}"} {:text "b"}]
- [{:text "abc"} {:action {:cmd :echo, :expression [12]}} O1 O2 O3 O4 O5 {:text "b"}]
+ [{:text "abc"} {:action {:cmd :echo, :expression [12] :raw "{%=12%}"}} O1 O2 O3 O4 O5 {:text "b"}]
 
  [O1 {:text "{%if p"} O2 O3 {:text "%}one{%end%}"} O4]
  [O1 {:text "{%if p"} O2 O3 {:text "%}one"} {:text "{%end%}"} O4]
- [O1 {:action {:cmd :if, :condition '[p]}} O2 O3 {:text "one"} {:action {:cmd :end}} O4] 
+ [O1 {:action {:cmd :if, :condition '[p] :raw "{%if p%}"}} O2 O3 {:text "one"} {:action {:cmd :end :raw "{%end%}"}} O4] 
  ))))

test/stencil/process_test.clj

@@ -28,7 +28,7 @@
  (is (= {:dynamic? true,
  :executable [{:open :a}
  {:open :b}
- {:stencil.cleanup/blocks [], :cmd :cmd/include, :name "elefant"}
+ {:stencil.cleanup/blocks [], :cmd :cmd/include, :name "elefant" :raw "{%include \"elefant\"%}"}
  {:close :b}
  {:close :a}],
  :fragments #{"elefant"}