Improving test failures feedback by extending IPrintWithWriter protocol in ClojureScript

When Francesc and I decided to directly store ClojureScript +, -, * and / functions in our Operation record instead of keywords representing them our code got simpler.

	(ns math-ops.operations
	(:require
	[math-ops.game-levels :as levels]))
	(defrecord Operation [op1 operator op2 res])
	(defn- hide-sth [operation]
	(assoc operation (rand-nth [:op1 :op2 :res]) :?))
	(defn- random-0-9 []
	(rand-int 10))
	(defn invertible? [level {:keys [op1 operator]}]
	(and (levels/allowed-operator? level operator)
	(not (and (= operator *) (= op1 0)))))
	(defn- invert [level operation]
	(if (invertible? level operation)
	(->Operation (:res operation)
	(levels/inverse-operator level (:operator operation))
	(:op1 operation)
	(:op2 operation))
	operation))
	(defn- invert-may-be [level operation]
	(if (rand-nth [true false])
	(invert level operation)
	operation))
	(defn make [level]
	(let [op1 (random-0-9)
	op2 (random-0-9)
	operator (levels/random-operator level)
	res (operator op1 op2)]
	(->> (->Operation op1 operator op2 res)
	(invert-may-be level)
	(hide-sth))))
	(defn- find-unknown [operation]
	(ffirst (filter #(= :? (second %)) operation)))
	(defn- substitute-unknown [operation guess]
	(assoc operation (find-unknown operation) guess))
	(defn- correct? [{:keys [res op1 op2 operator]}]
	(= res (operator op1 op2)))
	(defn correct-guess? [operation guess]
	(correct? (substitute-unknown operation guess)))

view raw operations_orig.cljs hosted with ❤ by GitHub

However the feedback we received when a test failed got much worse because the whole function got printed in the test failure output:

	$ lein doo node unit-tests
	Building ...
	Analyzing jar:file:/home/trikitrok/.m2/repository/org/clojure/clojurescript/1.7.170/clojurescript-1.7.170.jar!/cljs/core.cljs
	... done. Elapsed 2.32174747 seconds
	;; ======================================================================
	;; Testing with Node:
	Testing math-ops.operations-test
	FAIL in (operations-tests) (math_ops/operations_test.js:130:4)
	expected: (= some-non-invertible-operation (invert :max-level some-non-invertible-operation))
	actual: (not (= #math-ops.operations.Operation{:op1 1, :operator #object[cljs$core$_STAR_ "function cljs$core$_STAR_(var_args){
	var args6895 = [];
	var len__5318__auto___6901 = arguments.length;
	var i__5319__auto___6902 = (0);
	while(true){
	if((i__5319__auto___6902 < len__5318__auto___6901)){
	args6895.push((arguments[i__5319__auto___6902]));
	var G__6903 = (i__5319__auto___6902 + (1));
	i__5319__auto___6902 = G__6903;
	continue;
	} else {
	}
	break;
	}
	var G__6900 = args6895.length;
	switch (G__6900) {
	case 0:
	return cljs.core._STAR_.cljs$core$IFn$_invoke$arity$0();
	break;
	case 1:
	return cljs.core._STAR_.cljs$core$IFn$_invoke$arity$1((arguments[(0)]));
	break;
	case 2:
	return cljs.core._STAR_.cljs$core$IFn$_invoke$arity$2((arguments[(0)]),(arguments[(1)]));
	break;
	default:
	var argseq__5337__auto__ = (new cljs.core.IndexedSeq(args6895.slice((2)),(0)));
	return cljs.core._STAR_.cljs$core$IFn$_invoke$arity$variadic((arguments[(0)]),(arguments[(1)]),argseq__5337__auto__);
	}
	}"], :op2 0, :res 0} #math-ops.operations.Operation{:op1 0, :operator #object[cljs$core$_SLASH_ "function cljs$core$_SLASH_(var_args){
	var args6905 = [];
	var len__5318__auto___6911 = arguments.length;
	var i__5319__auto___6912 = (0);
	while(true){
	if((i__5319__auto___6912 < len__5318__auto___6911)){
	args6905.push((arguments[i__5319__auto___6912]));
	var G__6913 = (i__5319__auto___6912 + (1));
	i__5319__auto___6912 = G__6913;
	continue;
	} else {
	}
	break;
	}
	var G__6910 = args6905.length;
	switch (G__6910) {
	case 1:
	return cljs.core._SLASH_.cljs$core$IFn$_invoke$arity$1((arguments[(0)]));
	break;
	case 2:
	return cljs.core._SLASH_.cljs$core$IFn$_invoke$arity$2((arguments[(0)]),(arguments[(1)]));
	break;
	default:
	var argseq__5337__auto__ = (new cljs.core.IndexedSeq(args6905.slice((2)),(0)));
	return cljs.core._SLASH_.cljs$core$IFn$_invoke$arity$variadic((arguments[(0)]),(arguments[(1)]),argseq__5337__auto__);
	}
	}"], :op2 1, :res 0}))
	Testing math-ops.operations-guessing-test
	Ran 2 tests containing 18 assertions.
	1 failures, 0 errors.
	Watching paths: /home/trikitrok/Clojure/0_MiClojure/math-ops/src/cljs, /home/trikitrok/Clojure/0_MiClojure/math-ops/test

view raw not_useful_test_failure_feedback.sh hosted with ❤ by GitHub

The same happened when we were working on the REPL.

So we decided to extend the IPrintWithWriter protocol to improve the test failures feedback.

First, we tried to do it in the record declaration as we were doing for the Object protocol:

	(defrecord Operation [op1 operator op2 res]
	Object
	(toString [this] (operation->string this))
	IPrintWithWriter
	(-pr-writer [this writer _]
	(-write writer (operation->string this))))

view raw operation_implementing_protocols_in_record.cljs hosted with ❤ by GitHub

Surprisingly, it didn't work. We were still getting the ugly output shown before.

We were also getting this warning:

WARNING: Protocol IPrintWithWriter implemented multiple times at line 17 /home/trikitrok/Clojure/0_MiClojure/operations.cljs

view raw protocol_warning.txt hosted with ❤ by GitHub

So we tried with extend-protocol:

	(ns math-ops.operations
	(:require
	[math-ops.game-levels :as levels]
	[clojure.string :as string]))
	(def symbols-description
	{+ "+"
	- "-"
	* "x"
	/ "/"
	:? "?"})
	(defn- operation->string [{:keys [op1 operator op2 res]}]
	(string/join " " ["#Operation [" op1 (symbols-description operator) op2 "=" res "]"]))
	(defrecord Operation [op1 operator op2 res]
	Object
	(toString [this] (operation->string this)))
	(extend-protocol IPrintWithWriter
	Operation
	(-pr-writer [this writer _]
	(-write writer (operation->string this))))
	...
	...

view raw operations_useful_failure_feedback.cljs hosted with ❤ by GitHub

This worked as we expected and we got a more useful failure feedback:

	$ lein doo node unit-tests
	Building ...
	Analyzing jar:file:/home/trikitrok/.m2/repository/org/clojure/clojurescript/1.7.170/clojurescript-1.7.170.jar!/cljs/core.cljs
	... done. Elapsed 2.309172112 seconds
	;; ======================================================================
	;; Testing with Node:
	Testing math-ops.operations-test
	FAIL in (operations-tests) (math_ops/operations_test.js:130:4)
	expected: (= some-non-invertible-operation (invert :max-level some-non-invertible-operation))
	actual: (not (= #Operation [ 1 x 0 = 0 ] #Operation [ 0 / 1 = 0 ]))
	Testing math-ops.operations-guessing-test
	Ran 2 tests containing 18 assertions.
	1 failures, 0 errors.
	Watching paths: /home/trikitrok/Clojure/0_MiClojure/math-ops/src/cljs, /home/trikitrok/Clojure/0_MiClojure/math-ops/test

view raw useful_test_failure_feedback.sh hosted with ❤ by GitHub

It also worked using extend-type:

	...
	...
	(extend-type Operation
	IPrintWithWriter
	(-pr-writer [this writer _]
	(-write writer (operation->string this))))
	...
	...

view raw operations_useful_failure_feedback_using_extend_type.cljs hosted with ❤ by GitHub

Yet, we didn't understand why it was working as we expected with extend-type and extend-protocol but not in the declaration of the Operation record.

So we decided to ask it on the Clojurians slack.

There thanks to Alejandro Gómez and Nicolás Berger we understood what was happening. As Nicolás said:

That's the reason why it wasn't working and why we were getting that warning.

Check the code Nicolas is talking about in ClojureScript repository.

In the end, it was a nice problem to have, because we not only got a nicer and more useful failure feedback which was our initial goal, but also, learned more about extending core protocols in ClojureScript.

PS: Thank you very much to Alejandro Gómez and Nicolás Berger for their help.