Direct-linking changes lose line-number on invoke()

Description

(ns foo)  ;; 1
;; 2
;; 3
;; 4
;; 5
;; 6
;; 7
(defn callstack []                       ;; 8
  [1 2 3]                                ;; 9
  (throw (Exception. "whoopsie!")))      ;; 10

Stack Trace comparison. Only the first two lines of each trace are relevant, the rest is all REPL fluff.

;;; 1.7.0
{:cause "whoopsie!",
 :via
 [{:type java.lang.Exception,
   :message "whoopsie!",
   :at [foo$callstack invoke "foo.clj" 8]}],
 :trace
 [[foo$callstack invoke "foo.clj" 8]
  [user$eval7675 invoke "form-init3342294504880003721.clj" 1]
  [clojure.lang.Compiler eval "Compiler.java" 6782]
  [clojure.lang.Compiler eval "Compiler.java" 6745]
	...

;;; 1.8 RC2
{:cause "whoopsie!",
 :via
 [{:type java.lang.Exception,
   :message "whoopsie!",
   :at [foo$callstack invokeStatic "foo.clj" 8]}],
 :trace
 [[foo$callstack invokeStatic "foo.clj" 8]
  [foo$callstack invoke "foo.clj" -1]    ;; Unexpected: -1
  [user$eval4 invokeStatic "NO_SOURCE_FILE" 28]
  [user$eval4 invoke "NO_SOURCE_FILE" -1]    ;; Unexpected: -1
  [clojure.lang.Compiler eval "Compiler.java" 6913]
  [clojure.lang.Compiler eval "Compiler.java" 6876]
	...

;;; 1.8 RC2 with patch
{:cause "whoopsie!",
 :via
 [{:type java.lang.Exception,
   :message "whoopsie!",
   :at [foo$callstack invokeStatic "foo.clj" 8]}],
 :trace
 [[foo$callstack invokeStatic "foo.clj" 8]
  [foo$callstack invoke "foo.clj" 8]    ;; Fixed
  [user$eval4 invokeStatic "NO_SOURCE_FILE" 3]
  [user$eval4 invoke "NO_SOURCE_FILE" 3]   ;; Fixed
  [clojure.lang.Compiler eval "Compiler.java" 6917]
  [clojure.lang.Compiler eval "Compiler.java" 6880]
	...

Cause: Non-direct linking now calls from invoke() through to invokeStatic(). In invoke(), Compiler does not visitLineNumber() before invoke() calls invokeStatic(), meaning that stack traces end up with -1 instead of a useful line number.

Patch: CLJ-1854-more-context.patch

Screened by: Alex Miller

Environment

Clojure 1.8RC2, leiningen 2.5.1

Attachments

24 Nov 2015, 07:54 PM
24 Nov 2015, 06:53 PM

Activity

Show:

Gary Trakhman November 24, 2015 at 11:20 PM

Comparison of line numbers between 1.7 and 1.8 with patch here applied, clojure.test/do-report was modified to print stacktraces. It's weird that the numbers are different between parallel invoke/invokeStatic pairs.

diff --git a/src/clj/clojure/test.clj b/src/clj/clojure/test.clj
index 55e00f7..318ef20 100644
--- a/src/clj/clojure/test.clj
+++ b/src/clj/clojure/test.clj
@@ -349,7 +349,10 @@
   (report
    (case
     (:type m)
-    :fail (merge (file-and-line (new java.lang.Throwable) 1) m)
+     :fail (merge (file-and-line (doto (new java.lang.Throwable)
+                                   (.printStackTrace))
+                                 1)
+                  m)
     :error (merge (file-and-line (:actual m) 0) m) 
     m)))

1.7

gary@gary-dell:~/.m2/repository/org/clojure/clojure/1.7.0$ java -jar clojure-1.7.0.jar -r
Clojure 1.7.0
user=> (use 'clojure.test)
nil
user=> (deftest a []
(is false))
#'user/a
user=> (run-tests)

Testing user
java.lang.Throwable
    at clojure.test$do_report.invoke(test.clj:352)
    at user$fn__3.invoke(NO_SOURCE_FILE:3)
    at clojure.test$test_var$fn__7671.invoke(test.clj:707)
    at clojure.test$test_var.invoke(test.clj:707)
    at clojure.test$test_vars$fn__7693$fn__7698.invoke(test.clj:725)
    at clojure.test$default_fixture.invoke(test.clj:677)
    at clojure.test$test_vars$fn__7693.invoke(test.clj:725)
    at clojure.test$default_fixture.invoke(test.clj:677)
    at clojure.test$test_vars.invoke(test.clj:721)
    at clojure.test$test_all_vars.invoke(test.clj:731)
    at clojure.test$test_ns.invoke(test.clj:750)
    at clojure.core$map$fn__4553.invoke(core.clj:2624)
    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:1735)
    at clojure.lang.RestFn.applyTo(RestFn.java:130)
    at clojure.core$apply.invoke(core.clj:632)
    at clojure.test$run_tests.doInvoke(test.clj:765)
    at clojure.lang.RestFn.invoke(RestFn.java:408)
    at clojure.test$run_tests.invoke(test.clj:763)
    at user$eval7.invoke(NO_SOURCE_FILE:4)
    at clojure.lang.Compiler.eval(Compiler.java:6782)
    at clojure.lang.Compiler.eval(Compiler.java:6745)
    at clojure.core$eval.invoke(core.clj:3081)
    at clojure.main$repl$read_eval_print__7099$fn__7102.invoke(main.clj:240)
    at clojure.main$repl$read_eval_print__7099.invoke(main.clj:240)
    at clojure.main$repl$fn__7108.invoke(main.clj:258)
    at clojure.main$repl.doInvoke(main.clj:258)
    at clojure.lang.RestFn.invoke(RestFn.java:421)
    at clojure.main$repl_opt.invoke(main.clj:324)
    at clojure.main$main.doInvoke(main.clj:421)
    at clojure.lang.RestFn.invoke(RestFn.java:408)
    at clojure.lang.Var.invoke(Var.java:379)
    at clojure.lang.AFn.applyToHelper(AFn.java:154)
    at clojure.lang.Var.applyTo(Var.java:700)
    at clojure.main.main(main.java:37)

FAIL in (a) (NO_SOURCE_FILE:3)
expected: false
  actual: false

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

1.8 with patch here applied

gary@gary-dell:~/.m2/repository/org/clojure/clojure/1.8.0-master-SNAPSHOT$ java -jar clojure-1.8.0-master-SNAPSHOT.jar -r
Clojure 1.8.0-master-SNAPSHOT
user=> (use 'clojure.test)
nil
user=> (deftest a []
(is false))
#'user/a
user=> (run-tests)

Testing user
java.lang.Throwable
    at clojure.test$do_report.invokeStatic(test.clj:355)
    at clojure.test$do_report.invoke(test.clj:342)
    at user$fn__3.invokeStatic(NO_SOURCE_FILE:3)
    at user$fn__3.invoke(NO_SOURCE_FILE:2)
    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$eval7.invokeStatic(NO_SOURCE_FILE:4)
    at user$eval7.invoke(NO_SOURCE_FILE:4)
    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_opt.invokeStatic(main.clj:322)
    at clojure.main$repl_opt.invoke(main.clj:318)
    at clojure.main$main.invokeStatic(main.clj:421)
    at clojure.main$main.doInvoke(main.clj:384)
    at clojure.lang.RestFn.invoke(RestFn.java:408)
    at clojure.lang.Var.invoke(Var.java:379)
    at clojure.lang.AFn.applyToHelper(AFn.java:154)
    at clojure.lang.Var.applyTo(Var.java:700)
    at clojure.main.main(main.java:37)

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}
user=>

Gary Trakhman November 24, 2015 at 10:03 PM

I will make a separate ticket for the potential clojure.test change.

Alex Miller November 24, 2015 at 9:56 PM

@Gary Trakhman I think that issue should be a separate ticket if so.

Gary Trakhman November 24, 2015 at 9:47 PM

The current CLJ-1854-more-context.patch just gives me the same line number for all test cases, in my case it's test.clj:342 instead of -1 from before. I think perhaps clojure.test might need an adjustment as well, in particular the hardcoded '1' magic number here: https://github.com/clojure/clojure/blob/master/src/clj/clojure/test.clj#L351

test.clj:342 is do-report: https://github.com/clojure/clojure/blob/master/src/clj/clojure/test.clj#L342

Ghadi Shayban November 24, 2015 at 9:44 PM

Example has recursion through walk and is not minimal. Editing the ticket for reproducibility.

Completed

Details
Assignee
Unassigned
Reporter
Gary Trakhman
Labels
compilerregression
Approval
Ok
Patch
Code
Priority
Major
Affects versions
Release 1.8
Fix versions
Release 1.8

Created November 24, 2015 at 5:48 PM

Updated December 1, 2015 at 5:47 PM

Resolved December 1, 2015 at 5:47 PM

Configure

Direct-linking changes lose line-number on invoke()

Description

Environment

Attachments

Activity

Gary Trakhman November 24, 2015 at 11:20 PM

Gary Trakhman November 24, 2015 at 10:03 PM

Alex Miller November 24, 2015 at 9:56 PM

Gary Trakhman November 24, 2015 at 9:47 PM

Ghadi Shayban November 24, 2015 at 9:44 PM

DetailsAssigneeUnassignedUnassignedReporterGary TrakhmanGary TrakhmanLabelscompilerregressionApprovalOkPatchCodePriorityMajorAffects versionsRelease 1.8Fix versionsRelease 1.8

Details

Assignee

Reporter

Labels

Approval

Patch

Priority

Affects versions

Fix versions

Details
Assignee
Unassigned
Reporter
Gary Trakhman
Labels
compilerregression
Approval
Ok
Patch
Code
Priority
Major
Affects versions
Release 1.8
Fix versions
Release 1.8