Skip to content
Snippets Groups Projects
Unverified Commit 1a0f2d65 authored by John Swanson's avatar John Swanson Committed by GitHub
Browse files

Clarify stacktraces from malli validation errors (#34712) 

* Improve stacktraces for validation errors in malli-instrumented fns

First, when we throw exceptions in `metabase.util.malli/validate`, manually edit the stacktrace to remove those
StackTraceElements that start with `metabase.util.malli.fn`.

Second, instead of rewriting `mu/fn` bodies like so:

```
(let [f& ...] (fn [args] (do-validation) (f& args)))
```

Rewrite them like this:

```
(fn [args] (do-validation) ((fn [args'] ...) args))
```

I wasn't entirely sure that this wouldn't have a negative performance impact, so I tested it with these toy examples:

```
(def option-1
  (let [f (fn [x] (+ x 10))]
    (fn [x]
      (f x))))

(def option-2
  (fn [x]
    ((fn [x'] (+ x 10)) x)))
```

Then evaluated them with Criterium to benchmark.

The first option (our current behavior) looked like this:

```
Evaluation count : 10184236800 in 60 samples of 169737280 calls.
      Execution time sample mean : 4.117003 ns
             Execution time mean : 4.117119 ns
Execution time sample std-deviation : 0.017140 ns
    Execution time std-deviation : 0.017686 ns
   Execution time lower quantile : 4.100963 ns ( 2.5%)
   Execution time upper quantile : 4.149603 ns (97.5%)
                   Overhead used : 1.783065 ns
```

The second option (the new behavior) looked like this:

```
Evaluation count : 13861192260 in 60 samples of 231019871 calls.
      Execution time sample mean : 2.553532 ns
             Execution time mean : 2.553510 ns
Execution time sample std-deviation : 0.019674 ns
    Execution time std-deviation : 0.019824 ns
   Execution time lower quantile : 2.524266 ns ( 2.5%)
   Execution time upper quantile : 2.599826 ns (97.5%)
                   Overhead used : 1.783065 ns
```

So overall the performance does not look to be worse and may actually be slightly better.

In the end, we end up with stacktraces like:

```
(mu/defn bad-input :- :string
  [x :- :int]
  (str x))

(mu/defn bad-output :- :string
  [x :- :int]
  x)

(defn call-bad-input []
  (bad-input "1"))

(call-bad-input)

;;   Invalid input: ["should be an integer"]
;;   {:type :metabase.util.malli.fn/invalid-input,
;;    :error {:schema :int, :value "1", :errors ({:path [], :in [], :schema :int, :value "1"})},
;;    :humanized ["should be an integer"],
;;    :schema :int,
;;    :value "1",
;;    :fn-name playground/bad-input}
;;                      REPL:   19  playground/bad-input
;;                      REPL:   19  playground/bad-input
;;                      REPL:   28  playground/call-bad-input
;;                      REPL:   27  playground/call-bad-input

(defn call-bad-output []
  (bad-output 1))

(call-bad-output)

;;   Invalid output: ["should be a string"]
;;   {:type :metabase.util.malli.fn/invalid-output,
;;    :error {:schema :string, :value 1, :errors ({:path [], :in [], :schema :string, :value 1})},
;;    :humanized ["should be a string"],
;;    :schema :string,
;;    :value 1,
;;    :fn-name playground/bad-output}
;;                      REPL:   23  playground/bad-output
;;                      REPL:   23  playground/bad-output
;;                      REPL:   31  playground/call-bad-output
;;                      REPL:   30  playground/call-bad-output
```
parent ee66016f
Branches
Tags
No related merge requests found
Hide whitespace changes
Inline Side-by-side
src/metabase/util/malli/fn.clj
+ 42
− 20
View file @ 1a0f2d65
......@@ -2,6 +2,7 @@
(:refer-clojure :exclude [fn])
(:require
[clojure.core :as core]
[clojure.string :as str]
[malli.core :as mc]
[malli.destructure :as md]
[malli.error :as me]
......@@ -9,6 +10,8 @@
[metabase.util.malli.humanize :as mu.humanize]
[metabase.util.malli.registry :as mr]))
(set! *warn-on-reflection* true)
(defn- add-default-schemas
"Malli normally generates wacky default schemas when you use destructuring in an argslist; this never seems to work
correctly, so just add default schemas manually to circumvent Malli's weird behavior.
......@@ -143,20 +146,36 @@
use [[metabase.util.malli/disable-enforcement]] to bind this only in Clojure code."
true)
(defn- fixup-stacktrace
"This function removes stack trace elements that came from this namespace. When we throw validation errors, they
shouldn't originate from *this* namespace, they should appear to be thrown from the instrumented function itself."
[^Exception e]
(let [trace (.getStackTrace e)
fixed-trace (into-array StackTraceElement
(drop-while
#(str/starts-with? (.getClassName ^StackTraceElement %)
;; this is... hacky, but it works.
(namespace ::x))
trace))]
(.setStackTrace e fixed-trace)))
(defn- validate [error-context schema value error-type]
(when *enforce*
(when-let [error (mr/explain schema value)]
(let [humanized (me/humanize error)]
(throw (ex-info (case error-type
::invalid-input (i18n/tru "Invalid input: {0}" (pr-str humanized))
::invalid-output (i18n/tru "Invalid output: {0}" (pr-str humanized)))
(merge
{:type error-type
:error error
:humanized humanized
:schema schema
:value value}
error-context)))))))
(throw
(doto (ex-info
(case error-type
::invalid-input (i18n/tru "Invalid input: {0}" (pr-str humanized))
::invalid-output (i18n/tru "Invalid output: {0}" (pr-str humanized)))
(merge
{:type error-type
:error error
:humanized humanized
:schema schema
:value value}
error-context))
fixup-stacktrace))))))
(defn validate-input
"Impl for [[metabase.util.malli.fn/fn]]; validates an input argument with `value` against `schema` using a cached
......@@ -212,19 +231,19 @@
schemas)
(filter some?))))
(defn- input-schema->application-form [input-schema]
(defn- input-schema->application-form [input-schema deparameterized-fn]
(let [arg-names (input-schema-arg-names input-schema)]
(if (varargs-schema? input-schema)
(list* `apply '&f arg-names)
(list* '&f arg-names))))
(list* `apply deparameterized-fn arg-names)
(list* deparameterized-fn arg-names))))
(defn- instrumented-arity [error-context [_=> input-schema output-schema]]
(defn- instrumented-arity [error-context [_=> input-schema output-schema] deparameterized-fn]
(let [input-schema (if (= input-schema :cat)
[:cat]
input-schema)
arglist (input-schema->arglist input-schema)
input-validation-forms (input-schema->validation-forms error-context input-schema)
result-form (input-schema->application-form input-schema)
result-form (input-schema->application-form input-schema deparameterized-fn)
result-form (if (and output-schema
(not= output-schema :any))
`(->> ~result-form
......@@ -232,15 +251,17 @@
result-form)]
`(~arglist ~@input-validation-forms ~result-form)))
(defn- instrumented-fn-tail [error-context [schema-type :as schema]]
(defn- instrumented-fn-tail [error-context
[schema-type :as schema]
deparameterized-fn]
(case schema-type
:=>
[(instrumented-arity error-context schema)]
[(instrumented-arity error-context schema deparameterized-fn)]
:function
(let [[_function & schemas] schema]
(for [schema schemas]
(instrumented-arity error-context schema)))))
(instrumented-arity error-context schema deparameterized-fn)))))
(defn instrumented-fn-form
"Given a `fn-tail` like
......@@ -254,8 +275,9 @@
(mc/-instrument {:schema [:=> [:cat :int :any] :any]}
(fn [x y] (+ 1 2)))"
[error-context parsed]
`(let [~'&f ~(deparameterized-fn-form parsed)]
(core/fn ~@(instrumented-fn-tail error-context (fn-schema parsed)))))
`(core/fn ~@(instrumented-fn-tail error-context
(fn-schema parsed)
(deparameterized-fn-form parsed))))
(defmacro fn
"Malli version of [[schema.core/fn]]. A form like
......
test/metabase/util/malli/fn_test.clj
+ 43
− 35
View file @ 1a0f2d65
(ns ^:mb/once metabase.util.malli.fn-test
(:require
[clojure.string :as str]
[clojure.test :refer :all]
[clojure.walk :as walk]
[metabase.util.malli :as mu]
[metabase.util.malli.fn :as mu.fn]
[metabase.util.malli.registry :as mr]))
(set! *warn-on-reflection* true)
(deftest ^:parallel add-default-schemas-test
(are [input expected] (= expected
(#'mu.fn/add-default-schemas input))
......@@ -68,43 +71,44 @@
(are [form expected] (= expected
(walk/macroexpand-all (mu.fn/instrumented-fn-form {} (mu.fn/parse-fn-tail form))))
'([x :- :int y])
'(let* [&f (fn* ([x y]))]
(fn* ([a b]
(metabase.util.malli.fn/validate-input {} :int a)
(&f a b))))
'(fn* ([a b]
(metabase.util.malli.fn/validate-input {} :int a)
((fn* ([x y])) a b)))
'(:- :int [x :- :int y])
'(let* [&f (fn* ([x y]))]
(fn* ([a b]
(metabase.util.malli.fn/validate-input {} :int a)
(metabase.util.malli.fn/validate-output {} :int (&f a b)))))
'(fn* ([a b]
(metabase.util.malli.fn/validate-input {} :int a)
(metabase.util.malli.fn/validate-output {} :int ((fn* ([x y])) a b))))
'(:- :int [x :- :int y] (+ x y))
'(let* [&f (fn* ([x y] (+ x y)))]
(fn* ([a b]
(metabase.util.malli.fn/validate-input {} :int a)
(metabase.util.malli.fn/validate-output {} :int (&f a b)))))
'(fn* ([a b]
(metabase.util.malli.fn/validate-input {} :int a)
(metabase.util.malli.fn/validate-output {} :int ((fn* ([x y] (+ x y))) a b))))
'([x :- :int y] {:pre [(int? x)]})
'(let* [&f (fn* ([x y]
{:pre [(int? x)]}))]
(fn* ([a b]
(metabase.util.malli.fn/validate-input {} :int a)
(&f a b))))
'(fn* ([a b]
(metabase.util.malli.fn/validate-input {} :int a)
((fn* ([x y]
{:pre [(int? x)]}))
a b)))
'(:- :int
([x] (inc x))
([x :- :int y] (+ x y)))
'(let* [&f (fn* ([x]
(inc x))
([x y]
(+ x y)))]
(fn*
([a]
(metabase.util.malli.fn/validate-output {} :int (&f a)))
([a b]
(metabase.util.malli.fn/validate-input {} :int a)
(metabase.util.malli.fn/validate-output {} :int (&f a b)))))))
'(fn*
([a]
(metabase.util.malli.fn/validate-output {} :int ((fn* ([x]
(inc x))
([x y]
(+ x y)))
a)))
([a b]
(metabase.util.malli.fn/validate-input {} :int a)
(metabase.util.malli.fn/validate-output {} :int ((fn* ([x]
(inc x))
([x y]
(+ x y)))
a b))))))
(deftest ^:parallel fn-test
(let [f (mu.fn/fn :- :int [y] y)]
......@@ -115,7 +119,11 @@
(is (thrown-with-msg?
clojure.lang.ExceptionInfo
#"Invalid output:.*should be an integer"
(f nil)))))
(f nil)))
(testing "the stacktrace does not begin in the validation function"
(let [e ^Exception (is (thrown? clojure.lang.ExceptionInfo (f nil)))]
(is (not (str/starts-with? (.getClassName (first (.getStackTrace e)))
"metabase.util.malli.fn")))))))
(deftest ^:parallel registry-test
(mr/def ::number :int)
......@@ -141,13 +149,13 @@
& {:keys [token-check?]
:or {token-check? true}}]
(merge {:path path, :token-check? token-check?} opts))]
(is (= '(let* [&f (clojure.core/fn
[path opts & {:keys [token-check?], :or {token-check? true}}]
(merge {:path path, :token-check? token-check?} opts))]
(clojure.core/fn
([a b & more]
(metabase.util.malli.fn/validate-input {:fn-name 'my-fn} :map b)
(clojure.core/apply &f a b more))))
(is (= '(fn*
([a b & more]
(metabase.util.malli.fn/validate-input {:fn-name 'my-fn} :map b)
(clojure.core/apply (clojure.core/fn
[path opts & {:keys [token-check?], :or {token-check? true}}]
(merge {:path path, :token-check? token-check?} opts))
a b more)))
(macroexpand form)))
(is (= [:=>
[:cat :any :map [:* :any]]
......
0% or .
You are about to add 0 people to the discussion. Proceed with caution.
Please register or to comment