Improve backtrace looks and performance

[snogge]

Make the backtrace prints better - less unwanted output - with a lot better performance. Fixes #247 and #220.

[snogge]

@alphapapa @doublep @jcs090218 I did some major surgery on the backtrace code which really help with performance. I'll give you a few days to check it out before I merge. Let me know if I broke anything.

[alphapapa]

Hi Ola,

Thanks for the heads-up. I just did a quick test on the org-ql repo, both with all tests passing and with 104 out of 437 specs failing, and performance was excellent: instead of taking minutes to finish outputting the results and the backtraces, it happened in a matter of seconds. This is a great improvement. Thank you for working on it!

[jcs090218]

Thank you for notifying me. I've done a quick test, and it is working fine. :)

I've opened a PR in #250 to test downstream Eask and see if it works. This could make you more confident about the changes. 🤔

[doublep]

No tests in Eldev seem to broken with these changes.

However, it looks like the backtraces are not cut by Buttercup itself anymore (i.e. this is not because of Eldev). After intentionally corrupting one test, this is what I got in the branch (just ran make test, this is not through Eldev):

The buttercup--enclosed-expr function should handle expressions wrapped by buttercup--wrap-expr

Traceback (most recent call last):
  normal-top-level()
  command-line()
  command-line-1(("-L" "." "-l" "buttercup" "-f" "buttercup-run-discover" "-...
  buttercup-run-discover()
  buttercup-run()
  buttercup--run-suites((#s(buttercup-suite "The buttercup--enclosed-expr fu...
  mapc(buttercup--run-suite (#s(buttercup-suite "The buttercup--enclosed-exp...
  buttercup--run-suite(#s(buttercup-suite "The buttercup--enclosed-expr func...
  buttercup--run-suite(#s(buttercup-suite "should handle" #s(buttercup-suite...
  buttercup--run-spec(#s(buttercup-spec "expressions wrapped by buttercup--w...
  buttercup--update-with-funcall(#s(buttercup-spec "expressions wrapped by b...
  apply(buttercup--funcall (closure (t) nil (condition-case err (progn (butt...
  buttercup--funcall((closure (t) nil (condition-case err (progn (buttercup-...
  apply((closure (t) nil (condition-case err (progn (buttercup-expect (let (...
  (closure (t) nil (condition-case err (progn (buttercup-expect (let ((temp0...
  (condition-case err (progn (buttercup-expect (let ((temp0 '(buttercup--enc...
  (progn (buttercup-expect (let ((temp0 '(buttercup--enclosed-expr (buttercu...
  buttercup-expect((closure ((:type . buttercup--thunk) (expr buttercup--enc...
  buttercup-fail("%s" "Expected `(buttercup--enclosed-expr (buttercup--wrap-...
  signal(buttercup-failed "Expected `(buttercup--enclosed-expr (buttercup--w...
FAILED: Expected `(buttercup--enclosed-expr (buttercup--wrap-expr-and-eval '(ignore)))' to be `equal' to `(INTENTIONALLY-BROKEN-TEST)', but instead it was `(ignore)' which does not match because: (list-elt 0 (different-atoms ignore INTENTIONALLY-BROKEN-TEST)).

Ran 283 out of 284 specs, 1 failed, in 138.17ms.

For comparison, in master I get this instead:

The buttercup--enclosed-expr function should handle expressions wrapped by buttercup--wrap-expr

Traceback (most recent call last):
  buttercup-fail("%s" "Expected `(buttercup--enclosed-expr (buttercup--wrap-...
  signal(buttercup-failed "Expected `(buttercup--enclosed-expr (buttercup--w...
FAILED: Expected `(buttercup--enclosed-expr (buttercup--wrap-expr-and-eval '(ignore)))' to be `equal' to `(INTENTIONALLY-BROKEN-TEST)', but instead it was `(ignore)' which does not match because: (list-elt 0 (different-atoms ignore INTENTIONALLY-BROKEN-TEST)).

Also, the branch doesn't seem to add any new tests, which is suspicious for a big change.

[snogge]

@doublep , how can I recreate that?

[doublep]

~/git/buttercup$ git diff
diff --git a/tests/test-buttercup.el b/tests/test-buttercup.el
index 5172c46..02420b3 100644
--- a/tests/test-buttercup.el
+++ b/tests/test-buttercup.el
@@ -172,7 +172,7 @@ before it's processed by other functions."
   (describe "should handle"
     (it "expressions wrapped by buttercup--wrap-expr"
       (expect (buttercup--enclosed-expr (buttercup--wrap-expr-and-eval '(ignore)))
-              :to-equal '(ignore)))
+              :to-equal '(INTENTIONALLY-BROKEN-TEST)))
     (it "a closure with expression copy?"
       ;; This is for before Oclosures were added, and is not testable
       ;; once interpreted-function types were added in Emacs 30.
~/git/buttercup$ emacs --version
GNU Emacs 29.4.50
Development version c0ef9e766eb1 on emacs-29 branch; build date 2024-06-28.
Copyright (C) 2024 Free Software Foundation, Inc.
GNU Emacs comes with ABSOLUTELY NO WARRANTY.
You may redistribute copies of GNU Emacs
under the terms of the GNU General Public License.
For more information about these matters, see the file named COPYING.
~/git/buttercup$ make test
./bin/buttercup -L . tests 
[...]

Traceback (most recent call last):
  normal-top-level()
  command-line()
  command-line-1(("-L" "." "-l" "buttercup" "-f" "buttercup-run-discover" "-...
  buttercup-run-discover()
  buttercup-run()
  buttercup--run-suites((#s(buttercup-suite "The buttercup--enclosed-expr fu...
  mapc(buttercup--run-suite (#s(buttercup-suite "The buttercup--enclosed-exp...
  buttercup--run-suite(#s(buttercup-suite "The buttercup--enclosed-expr func...
  buttercup--run-suite(#s(buttercup-suite "should handle" #s(buttercup-suite...
  buttercup--run-spec(#s(buttercup-spec "expressions wrapped by buttercup--w...
  buttercup--update-with-funcall(#s(buttercup-spec "expressions wrapped by b...
  apply(buttercup--funcall (closure (t) nil (condition-case err (progn (butt...
  buttercup--funcall((closure (t) nil (condition-case err (progn (buttercup-...
  apply((closure (t) nil (condition-case err (progn (buttercup-expect (let (...
  (closure (t) nil (condition-case err (progn (buttercup-expect (let ((temp0...
  (condition-case err (progn (buttercup-expect (let ((temp0 '(buttercup--enc...
  (progn (buttercup-expect (let ((temp0 '(buttercup--enclosed-expr (buttercu...
  buttercup-expect((closure ((:type . buttercup--thunk) (expr buttercup--enc...
  buttercup-fail("%s" "Expected `(buttercup--enclosed-expr (buttercup--wrap-...
  signal(buttercup-failed "Expected `(buttercup--enclosed-expr (buttercup--w...
FAILED: Expected `(buttercup--enclosed-expr (buttercup--wrap-expr-and-eval '(ignore)))' to be `equal' to `(INTENTIONALLY-BROKEN-TEST)', but instead it was `(ignore)' which does not match because: (list-elt 0 (different-atoms ignore INTENTIONALLY-BROKEN-TEST)).

Ran 283 out of 284 specs, 1 failed, in 138.10ms.
buttercup-run failed: ""
make: *** [Makefile:12: check-buttercup] Error 255

[snogge]

I think that is because of buttercup nesting itself. It fails to find the correct bounds of the backtrace because there are two sets of them. While this is annoying, it feels less important than normal use. If you can recreate it with another package I would really like to know about it. For the original problem in org-ql I see the opposite:

org-ql View saving/loading Links Buffers/Files Can search multiple files by filename

Traceback (most recent call last):
  #[899 "\306\307\"A@\306\310\"A@\306\311\"\206\312\302\242DA@\306\313...
  #[771 "rq\210\300 \210\301 \210\302c\210c\210\303u\210\211\204\304\305...
  with-simulated-input-1(#[0 "\300 \207" [org-open-at-point] 1] nil)
  signal(invalid-function (("\"ORG-QL-TEST\"")))
error: (invalid-function ("\"ORG-QL-TEST\""))

instead of

org-ql View saving/loading Links Buffers/Files Can search multiple files by filename
/
Traceback (most recent call last):
  normal-top-level()
  command-line()
  command-line-1(("--title" "makem.sh: org-ql (sandbox: sandbox/31.0.50)" "-...
  eval((progn (setq backtrace-on-error-noninteractive nil) (buttercup-run)) t)
  (progn (setq backtrace-on-error-noninteractive nil) (buttercup-run))
  buttercup-run()
  apply(makem-buttercup-run #[256 \203	\30\"\207\211\203\302\207\303...
  makem-buttercup-run(#[256 \203	\30\"\207\211\203\302\207\303\304!\...
  (if buttercup-suites (progn (apply oldfun r)))
  (progn (apply oldfun r))
  apply(#[256 \203	\30\"\207\211\203\302\207\303\304!\207" [buttercu...
  #[256 \203	\30\"\207\211\203\302\207\303\304!\207" [buttercup-suit...
  buttercup--run-suites((#s(buttercup-suite "org-ql" nil passed org-ql-test-...
  mapc(buttercup--run-suite (#s(buttercup-suite "org-ql" nil passed org-ql-t...
  buttercup--run-suite(#s(buttercup-suite "org-ql" nil passed org-ql-test-or...
  buttercup--run-suite(#s(buttercup-suite "View saving/loading" #s(buttercup...
  buttercup--run-suite(#s(buttercup-suite "Links" #s(buttercup-suite "View s...
  buttercup--run-suite(#s(buttercup-suite "Buffers/Files" #s(buttercup-suite...
  buttercup--run-spec(#s(buttercup-spec "Can search multiple files by filena...
  buttercup--update-with-funcall(#s(buttercup-spec "Can search multiple file...
  apply(buttercup--funcall #[0 "\3031 \3041�\305\306\307\310\300\301\302%\...
  buttercup--funcall(#[0 "\3031 \3041�\305\306\307\310\300\301\302%\311\30...
  apply(#[0 "\3031 \3041�\305\306\307\310\300\301\302%\311\306\312\313\302...
  #[0 "\3031 \3041�\305\306\307\310\300\301\302%\311\306\312\313\302##00\2...
  buttercup-expect(#[0 "\302\304\303\301\305\306%\207" [(var-after-link-save...
  buttercup--apply-matcher(:to-equal (#[0 "\302\304\303\301\305\306%\207" [(...
  apply(#[514 "\300\301D\"\211G\302U\203\211A\262\242\202\303\304\30...
  #[514 "\300\301D\"\211G\302U\203\211A\262\242\202\303\304\305GD\"...
  mapcar(buttercup--expr-and-value (#[0 "\302\304\303\301\305\306%\207" [(va...
  buttercup--expr-and-value(#[0 "\302\304\303\301\305\306%\207" [(var-after-...
  #[0 "\302\304\303\301\305\306%\207" [(var-after-link-save-open 'org-ql-vie...
  #[899 "\306\307\"A@\306\310\"A@\306\311\"\206\312\302\242DA@\306\313...
  #[771 "rq\210\300 \210\301 \210\302c\210c\210\303u\210\211\204\304\305...
  with-simulated-input-1(#[0 "\300 \207" [org-open-at-point] 1] nil)
  signal(invalid-function (("\"ORG-QL-TEST\"")))
error: (invalid-function ("\"ORG-QL-TEST\""))

[snogge]

Hmm, but that specific test is not nested. I'll have to look further.

[doublep]

If you can recreate it with another package I would really like to know about it.

I originally noticed it with test/project-e in Eldev's test suite. I did run Buttercup inside Eldev, so initially I suspected that something got broken in my integration code because of these changes. Then I retested it without Eldev at all, on Buttercup directly, and saw the same problem. So, I'm pretty sure that it's a problem with this branch and most likely it's not about nesting level, because it seems to happen both in Buttercup and in unrelated projects.

[snogge]

I think I'm on to something now. The new code works great for unexpected errors in code called from within an except statement. That's why it works for the failing org-ql tests - there was a bug in org-ql that caused invalid-function errors. Code outside except is not handled well on this branch. The problem with the failing test in buttercup is actually different. That is just a test-mismatch and should really not collect any backtrace at all. What's a meaningful backtrace for (expect 1 :to-equal 0)? There are a few other corner cases that have to be handled as well, like errors in the matcher or in before/after blocks.

[snogge]

Newer and even more improved. Now also with tests. @doublep, the problems you reported should be fixed now. @jcs090218 , the tests in #250 passes on this branch.

[snogge]

No comments for more than a week, merging this now.