<< Back to previous view

[CLJ-1856] Direct-linking breaks clojure.test do-report stack-depth assumptions for failure reporting. Created: 24/Nov/15  Updated: 25/Nov/15

Status: Open
Project: Clojure
Component/s: None
Affects Version/s: Release 1.8
Fix Version/s: Release 1.8

Type: Defect Priority: Major
Reporter: Gary Trakhman Assignee: Unassigned
Resolution: Unresolved Votes: 0
Labels: regression, test

Attachments: Text File clj-1856.patch    
Patch: Code
Approval: Vetted


Test failure locations are being mis-reported (wrong class/line number).

Given a test ns:

(ns test1856.core-test
  (:require [clojure.test :refer :all]
            [test1856.core :refer :all]))

(deftest fail-test
  ;; 6
  ;; 7
  (is (= nil true)))  ;; 8

The results with 1.8-RC2 (with CLJ-1854 patch included) are:

FAIL in (fail-test) (test.clj:342)    ;; WRONG, expected: (core_test.clj:8)
expected: (= nil true)
  actual: (not (= nil true))

Cause: The location of the error is calculated in test.clj by constructing a Throwable in do-report and then dropping the top 1 frame (which is do-report itself) to find the user frame where the assertion failed. However, with direct linking there are now 2 frames on top of of the failure in user code, so the same (incorrect) location in test.clj is reported every time.

Approach: Change to a different strategy to filter the top frames based on content, not hard-coded depth. This strategy will work regardless of whether direct linking is involved or not.

1. Instead of constructing an exception and using it's stack trace, instead call Thread.getStackTrace() on the current thread. Create a new function that works on stack traces rather than exceptions and no longer needs a depth check.
2. Drop top frames while their class name starts with java.lang (this filters the call to java.lang.Thread.getStackTrace()) or clojure.test. The top frame will then be in the user's code.
3. Deprecated old file-and-line function (not sure if other clojure test reporting frameworks use this, despite it being private).
4. Updated tests that check that these functions work with an empty stack trace, as the JVM may elide it.

Patch: clj-1856.patch

Comment by Gary Trakhman [ 24/Nov/15 4:35 PM ]

'2' works in the standard case of direct-linked clojure with non-direct-linked app code. I'm exploring if there's a way to get the line info via macro-expansion of 'try-expr' and passing the line value into do-report for those cases.

Comment by Gary Trakhman [ 24/Nov/15 4:54 PM ]

I altered a local clojure build to print the stacktrace of the Throwable created by do-report, showing the additional invokeStatic frames during a repl session, showing the first user function frame is at offset 2.

user> (use 'clojure.test)
user> (deftest a []
        (is false))
user> (run-tests)

Testing user

FAIL in (a) (test.clj:342)
expected: false
  actual: false

Ran 1 tests containing 1 assertions.
1 failures, 0 errors.
{:test 1, :pass 0, :fail 1, :error 0, :type :summary}

    at clojure.test$do_report.invokeStatic(test.clj:355)
    at clojure.test$do_report.invoke(test.clj:342)
    at user$fn__16867.invokeStatic(NO_SOURCE_FILE:74)
    at user$fn__16867.invoke(NO_SOURCE_FILE:73)
    at clojure.test$test_var$fn__7973.invoke(test.clj:706)
    at clojure.test$test_var.invokeStatic(test.clj:706)
    at clojure.test$test_var.invoke(test.clj:697)
    at clojure.test$test_vars$fn__7995$fn__8000.invoke(test.clj:724)
    at clojure.test$default_fixture.invokeStatic(test.clj:676)
    at clojure.test$default_fixture.invoke(test.clj:672)
    at clojure.test$test_vars$fn__7995.invoke(test.clj:724)
    at clojure.test$default_fixture.invokeStatic(test.clj:676)
    at clojure.test$default_fixture.invoke(test.clj:672)
    at clojure.test$test_vars.invokeStatic(test.clj:720)
    at clojure.test$test_all_vars.invokeStatic(test.clj:726)
    at clojure.test$test_ns.invokeStatic(test.clj:747)
    at clojure.test$test_ns.invoke(test.clj:732)
    at clojure.core$map$fn__4781.invoke(core.clj:2648)
    at clojure.lang.LazySeq.sval(LazySeq.java:40)
    at clojure.lang.LazySeq.seq(LazySeq.java:49)
    at clojure.lang.Cons.next(Cons.java:39)
    at clojure.lang.RT.boundedLength(RT.java:1749)
    at clojure.lang.RestFn.applyTo(RestFn.java:130)
    at clojure.core$apply.invokeStatic(core.clj:647)
    at clojure.test$run_tests.invokeStatic(test.clj:757)
    at clojure.test$run_tests.doInvoke(test.clj:757)
    at clojure.lang.RestFn.invoke(RestFn.java:408)
    at clojure.test$run_tests.invokeStatic(test.clj:762)
    at clojure.test$run_tests.invoke(test.clj:757)
    at user$eval16871.invokeStatic(NO_SOURCE_FILE:76)
    at user$eval16871.invoke(NO_SOURCE_FILE:76)
    at clojure.lang.Compiler.eval(Compiler.java:6915)
    at clojure.lang.Compiler.eval(Compiler.java:6878)
    at clojure.core$eval.invokeStatic(core.clj:3107)
    at clojure.core$eval.invoke(core.clj:3103)
    at clojure.main$repl$read_eval_print__7402$fn__7405.invoke(main.clj:240)
    at clojure.main$repl$read_eval_print__7402.invoke(main.clj:240)
    at clojure.main$repl$fn__7411.invoke(main.clj:258)
    at clojure.main$repl.invokeStatic(main.clj:258)
    at clojure.main$repl.doInvoke(main.clj:174)
    at clojure.lang.RestFn.invoke(RestFn.java:1523)
    at clojure.tools.nrepl.middleware.interruptible_eval$evaluate$fn__10251.invoke(interruptible_eval.clj:87)
    at clojure.lang.AFn.applyToHelper(AFn.java:152)
    at clojure.lang.AFn.applyTo(AFn.java:144)
    at clojure.core$apply.invokeStatic(core.clj:645)
    at clojure.core$with_bindings_STAR_.invokeStatic(core.clj:1883)
    at clojure.core$with_bindings_STAR_.doInvoke(core.clj:1883)
    at clojure.lang.RestFn.invoke(RestFn.java:425)
    at clojure.tools.nrepl.middleware.interruptible_eval$evaluate.invokeStatic(interruptible_eval.clj:85)
    at clojure.tools.nrepl.middleware.interruptible_eval$evaluate.invoke(interruptible_eval.clj:55)
    at clojure.tools.nrepl.middleware.interruptible_eval$interruptible_eval$fn__10296$fn__10299.invoke(interruptible_eval.clj:222)
    at clojure.tools.nrepl.middleware.interruptible_eval$run_next$fn__10291.invoke(interruptible_eval.clj:190)
    at clojure.lang.AFn.run(AFn.java:22)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at java.lang.Thread.run(Thread.java:745)

This is also with the patch from http://dev.clojure.org/jira/browse/CLJ-1854 applied

Comment by Alex Miller [ 25/Nov/15 1:26 PM ]
(ns test1856.core-test
  (:require [clojure.test :refer :all]
            [test1856.core :refer :all]))

(deftest throw-test
  ;; 6
  ;; 7
  (is (= nil (throw (Exception. "abc")))))  ;; 8

(deftest fail-test
  ;; 11
  ;; 12
  (is (= nil true)))  ;; 13

If I lein test (or run from repl), I see:

;; 1.7
FAIL in (fail-test) (core_test.clj:13)
expected: (= nil true)
  actual: (not (= nil true))

ERROR in (throw-test) (core_test.clj:8)
expected: (= nil (throw (Exception. "abc")))
  actual: java.lang.Exception: abc
 at test1856.core_test/fn (core_test.clj:8)
    clojure.test$test_var$fn__7670.invoke (test.clj:704)
    clojure.test$test_var.invoke (test.clj:704)
    clojure.test$test_vars$fn__7692$fn__7697.invoke (test.clj:722)
;; 1.8.0-RC2 + CLJ-1854 patch
FAIL in (fail-test) (test.clj:342)    ;; ERROR
expected: (= nil true)
  actual: (not (= nil true))

ERROR in (throw-test) (core_test.clj:8)
expected: (= nil (throw (Exception. "abc")))
  actual: java.lang.Exception: abc
 at test1856.core_test$fn__201.invokeStatic (core_test.clj:8)  ;; OK
    test1856.core_test/fn (core_test.clj:5)
    clojure.test$test_var$fn__7972.invoke (test.clj:703)
    clojure.test$test_var.invokeStatic (test.clj:703)

Generated at Tue Dec 01 16:10:10 CST 2015 using JIRA 4.4#649-r158309.