bug#28333: 26.0.50; Backtrace not printed when ERT test fails

bug#28333: 26.0.50; Backtrace not printed when ERT test fails

[Gemini Lasswell]

ERT used to print a backtrace for every failed test, but recently that
stopped happening. I git bisected and found that the commit which
introduced the problem is ead545824e, "Improve ert backtrace
recording".

Here's the test I've been using to reproduce the problem:

(require 'ert)
(defun div0 (n)
  (/ n (- n n)))
(ert-deftest failing-test ()
  "Check if backtrace works"
  (should (div0 1)))

When running the test interactively, pressing b at the test in ERT's
results buffer shows an empty backtrace. And here is the output of
running "make -C test fail" with the code above saved in
test/lisp/fail.el:

make: Entering directory '/home/gemini/src/emacs/test'
make[1]: Entering directory '/home/gemini/src/emacs/test'
  GEN      lisp/fail.log
Running 1 tests (2017-09-02 11:46:08-0700)
Test failing-test backtrace:
Test failing-test condition:
    (arith-error)
   FAILED  1/1  failing-test

Ran 1 tests, 0 results as expected, 1 unexpected (2017-09-02 11:46:08-0700)

1 unexpected results:
   FAILED  failing-test

make[1]: *** [Makefile:149: lisp/fail.log] Error 1
make[1]: Leaving directory '/home/gemini/src/emacs/test'
make: *** [Makefile:198: lisp/fail] Error 2
make: Leaving directory '/home/gemini/src/emacs/test'


In GNU Emacs 26.0.50 (build 6, x86_64-pc-linux-gnu, GTK+ Version 3.22.8)
 of 2017-09-02 built on chinook
Repository revision: ead545824e511ab18d18b5223eab80e1f4fe3d64
Windowing system distributor 'The X.Org Foundation', version 11.0.11902000
Recent messages:
Guessed variable ’python-indent’ (2)
You should have a section marked ";;; Commentary:"

The first line should be of the form: ";;; package --- Summary"
You can run the command ‘eval-buffer’ with M-x ev-b RET
Ran 1 tests, 0 results were as expected, 1 unexpected
You can run the command ‘ert’ with M-x ert RET
Ran 1 tests, 0 results were as expected, 1 unexpected
mouse-2, RET: Reveal test result
mouse-2, RET: Expand/collapse test result

Configured using:
 'configure --prefix=/home/gemini/src/emacs/out --with-modules
 --with-x-toolkit=gtk3 --with-xft --config-cache'

Configured features:
XPM JPEG TIFF GIF PNG RSVG SOUND DBUS GSETTINGS NOTIFY LIBSELINUX
GNUTLS LIBXML2 FREETYPE XFT ZLIB TOOLKIT_SCROLL_BARS GTK3 X11 MODULES

Important settings:
  value of $LANG: en_US.UTF-8
  locale-coding-system: utf-8-unix

Major mode: ERT-View

Minor modes in effect:
  ivy-mode: t
  global-flycheck-mode: t
  pyvenv-mode: t
  beacon-mode: t
  shell-dirtrack-mode: t
  imagex-auto-adjust-mode: t
  volatile-highlights-mode: t
  region-state-mode: t
  ws-butler-global-mode: t
  ws-butler-mode: t
  show-smartparens-global-mode: t
  smartparens-global-mode: t
  smartparens-global-strict-mode: t
  which-key-mode: t
  modalka-global-mode: t
  modalka-mode: t
  global-auto-revert-mode: t
  winner-mode: t
  savehist-mode: t
  override-global-mode: t
  cl-old-struct-compat-mode: t
  tooltip-mode: t
  global-eldoc-mode: t
  electric-indent-mode: t
  mouse-wheel-mode: t
  file-name-shadow-mode: t
  global-font-lock-mode: t
  font-lock-mode: t
  auto-composition-mode: t
  auto-encryption-mode: t
  auto-compression-mode: t
  buffer-read-only: t
  size-indication-mode: t
  column-number-mode: t
  line-number-mode: t
  transient-mark-mode: t

Load-path shadows:
None found.

Features:
(ert ewoc debug colir counsel swiper ivy flx delsel ivy-overlay ffap
shadow sort mail-extr emacsbug flycheck sji-sunset-day-theme
guess-style company-capf company-files mu4e desktop frameset
mu4e-speedbar speedbar sb-image ezimage dframe mu4e-main mu4e-context
mu4e-view mu4e-headers mu4e-compose mu4e-draft mu4e-actions rfc2368
smtpmail sendmail mu4e-mark mu4e-message html2text mu4e-proc
mu4e-utils doc-view jka-compr mu4e-lists mu4e-vars message rfc822 mml
mml-sec epa derived epg gnus-util rmail rmail-loaddefs mailabbrev
mail-utils gmm-utils mailheader hl-line mu4e-meta company-tern
dash-functional tern company-jedi jedi-core python-environment epc
ctable concurrent deferred company-c-headers nix-mode yasnippet
highlight-indentation flymake help-fns radix-tree elpy pyvenv
elpy-django elpy-refactor smartparens-python python tramp-sh json map
grep files-x slime-fancy slime-trace-dialog slime-fontifying-fu
slime-package-fu slime-references slime-compiler-notes-tree
slime-scratch slime-presentations bridge slime-macrostep macrostep
slime-mdot-fu slime-enclosing-context slime-fuzzy slime-fancy-trace
slime-fancy-inspector slime-c-p-c slime-editing-commands slime-autodoc
slime-repl slime-parse slime-company company pcase slime compile
arc-mode archive-mode pp hyperspec browse-url nameless lisp-mnt
ace-window avy beacon smex ido tramp tramp-compat tramp-loaddefs
trampver shell parse-time image+ ledger-mode ledger-check
ledger-schedule ledger-xact ledger-texi ledger-test ledger-sort
ledger-report ledger-reconcile ledger-post ledger-occur ledger-init
ledger-fontify ledger-state ledger-navigate ledger-fonts ledger-exec
ledger-context ledger-complete ledger-commodities esh-var esh-io
esh-cmd esh-opt esh-ext esh-proc esh-groups eshell esh-module esh-mode
esh-arg esh-util cus-edit cus-start cus-load ledger-regex rx deft
wid-edit debbugs soap-client mm-decode mm-bodies mm-encode url-http
tls gnutls url-auth mail-parse rfc2231 rfc2047 rfc2045 mm-util
ietf-drums mail-prsvr url-gw nsm subr-x puny url url-proxy url-privacy
url-expand url-methods url-history url-cookie url-domsuf url-util
mailcap warnings rng-xsd rng-dt rng-util xsd-regexp xml rainbow-mode
color s ucs-normalize hydra lv column-enforce-mode etags xref project
volatile-highlights region-state ws-butler smartparens-config
smartparens thingatpt dash which-key modalka quail
smart-mode-line-respectful-theme smart-mode-line rich-minority
sji-sunset-night-theme color-theme-sji-sunset advice dired+
image-dired image-mode image-file dired-x dired-aux dired
dired-loaddefs autorevert filenotify winner savehist cap-words
superword subword org-clock org org-macro org-footnote org-pcomplete
pcomplete org-list org-faces org-entities noutline outline org-version
ob-emacs-lisp ob ob-tangle ob-ref ob-lob ob-table ob-exp org-src
ob-keys ob-comint comint ansi-color ring ob-core ob-eval org-compat
org-macs org-loaddefs format-spec find-func cal-menu calendar
cal-loaddefs cl-extra help-mode use-package diminish bind-key
easy-mmode finder-inf edmacro kmacro slime-autoloads info cl package
easymenu epg-config url-handlers url-parse auth-source cl-seq eieio
eieio-core cl-macs eieio-loaddefs password-cache url-vars seq byte-opt
gv bytecomp byte-compile cconv cl-loaddefs cl-lib time-date mule-util
tooltip eldoc electric uniquify ediff-hook vc-hooks lisp-float-type
mwheel term/x-win x-win term/common-win x-dnd tool-bar dnd fontset
image regexp-opt fringe tabulated-list replace newcomment text-mode
elisp-mode lisp-mode prog-mode register page menu-bar rfn-eshadow
isearch timer select scroll-bar mouse jit-lock font-lock syntax
facemenu font-core term/tty-colors frame cl-generic cham georgian
utf-8-lang misc-lang vietnamese tibetan thai tai-viet lao korean
japanese eucjp-ms cp51932 hebrew greek romanian slovak czech european
ethiopic indian cyrillic chinese composite charscript charprop
case-table epa-hook jka-cmpr-hook help simple abbrev obarray
minibuffer cl-preloaded nadvice loaddefs button faces cus-face
macroexp files text-properties overlay sha1 md5 base64 format env
code-pages mule custom widget hashtable-print-readable backquote
dbusbind inotify dynamic-setting system-font-setting
font-render-setting move-toolbar gtk x-toolkit x multi-tty
make-network-process emacs)

Memory information:
((conses 16 638543 375725)
 (symbols 48 55060 42)
 (miscs 40 246 528)
 (strings 32 151320 46615)
 (string-bytes 1 4521307)
 (vectors 16 81725)
 (vector-slots 8 1291449 454954)
 (floats 8 404 736)
 (intervals 56 1261 463)
 (buffers 976 17))

bug#28333: 26.0.50; Backtrace not printed when ERT test fails

[Noam Postavsky]

tag 28333 confirmed
quit

On Sat, Sep 2, 2017 at 3:20 PM, Gemini Lasswell <gazally@runbox.com> wrote:
> ERT used to print a backtrace for every failed test, but recently that
> stopped happening. I git bisected and found that the commit which
> introduced the problem is ead545824e, "Improve ert backtrace
> recording".

Hah, ironic isn't it. The problem is this code here:

              ;; Grab the frames starting from `signal', frames below
              ;; that are all from the debugger.
              (backtrace (backtrace-frames 'signal))

When the error comes from division by 0, there is `signal' frame at
all, hence we store `nil' as the backtrace. Maybe this could be fixed
with something equivalent to the following?

--- i/lisp/emacs-lisp/ert.el
+++ w/lisp/emacs-lisp/ert.el
@@ -739,7 +739,8 @@ ert--run-test-debugger
               ;;
               ;; Grab the frames starting from `signal', frames below
               ;; that are all from the debugger.
-              (backtrace (backtrace-frames 'signal))
+              (backtrace (or (backtrace-frames 'signal)
+                             (cdr (backtrace-frames 'ert--run-test-debugger))))
               (infos (reverse ert--infos)))
          (setf (ert--test-execution-info-result info)
                (cl-ecase type

bug#28333: 26.0.50; Backtrace not printed when ERT test fails

[Gemini Lasswell]

Noam Postavsky writes:

> Maybe this could be fixed with something equivalent to the following?

I've been running this for a few days and haven't seen any more missing
backtraces.

bug#28333: 26.0.50; Backtrace not printed when ERT test fails

[Noam Postavsky]

[-- Attachment #1: Type: text/plain, Size: 374 bytes --]

tags 28333 + patch
quit

Gemini Lasswell <gazally@runbox.com> writes:

> Noam Postavsky writes:
>
>> Maybe this could be fixed with something equivalent to the following?
>
> I've been running this for a few days and haven't seen any more missing
> backtraces.

Actually, I think it's giving one extra frame.  Using `debugger' as the
BASE seems to cover both cases nicely:


[-- Warning: decoded text below may be mangled, UTF-8 assumed --]
[-- Attachment #2: patch --]
[-- Type: text/x-diff, Size: 1211 bytes --]

From 847ed811022f4d4fe43f2d5e14660f93538423dd Mon Sep 17 00:00:00 2001
From: Noam Postavsky <npostavs@gmail.com>
Date: Sat, 23 Sep 2017 11:40:14 -0400
Subject: [PATCH] Fix ert backtrace saving for non-`signal'ed errors
 (Bug#28333)

* lisp/emacs-lisp/ert.el (ert--run-test-debugger): Take the frames
above the `debugger' frame, rather than assuming there will be a
`signal' frame.
---
 lisp/emacs-lisp/ert.el | 5 ++---
 1 file changed, 2 insertions(+), 3 deletions(-)

diff --git a/lisp/emacs-lisp/ert.el b/lisp/emacs-lisp/ert.el
index d4276221ba..83acbacb88 100644
--- a/lisp/emacs-lisp/ert.el
+++ b/lisp/emacs-lisp/ert.el
@@ -742,9 +742,8 @@ ert--run-test-debugger
               ;; backtrace ready for printing is important for batch
               ;; use.
               ;;
-              ;; Grab the frames starting from `signal', frames below
-              ;; that are all from the debugger.
-              (backtrace (backtrace-frames 'signal))
+              ;; Grab the frames above the debugger.
+              (backtrace (cdr (backtrace-frames debugger)))
               (infos (reverse ert--infos)))
          (setf (ert--test-execution-info-result info)
                (cl-ecase type
-- 
2.11.0

bug#28333: 26.0.50; Backtrace not printed when ERT test fails

[Noam Postavsky]

tags 28333 fixed
close 28333
quit

Noam Postavsky <npostavs@users.sourceforge.net> writes:

> Actually, I think it's giving one extra frame.  Using `debugger' as the
> BASE seems to cover both cases nicely:

Pushed to emacs-26.

[1: af130f900f]: 2017-09-28 19:57:24 -0400
  Fix ert backtrace saving for non-`signal'ed errors (Bug#28333)
  http://git.savannah.gnu.org/cgit/emacs.git/commit/?id=af130f900fc499f71ea22f10ba055a75ce35ed4e