bug#67862: 30.0.50; Handler-bind and ert-test-error-debug

["J.P." <jp@neverwas.me>]

Hi Stefan,

Apologies if this is old news, but I think I've noticed a difference in
ERT's behavior that may align with this feature's introduction.

With a snippet like this somewhere in lisp/emacs-lisp/ert-tests.el:

  (ert-deftest my-baseline ()
    (error "Done wrong"))

  (ert-deftest my-filter ()
    (let ((proc
           (start-process "my-filter" (current-buffer) "sh" "-c"
                          "for i in $(seq 99); do echo $i; sleep 0.01; done")))
      (set-process-filter proc
                          (lambda (_ string)
                            (when (string-search "42" string)
                              (error "Encountered bad value"))))
      (with-timeout (5 (ert-fail "Timed out"))
        (while (process-live-p proc)
          (accept-process-output nil 0.01)))))

  (ert-deftest my-timer ()
    (run-at-time 0.2 nil (lambda () (error "Encountered a problem")))
    (with-timeout (5 (ert-fail "Timed out"))
      (while (accept-process-output nil 5))))

Run

  $ make -C test SELECTOR=my-baseline lisp/emacs-lisp/ert-tests.log
  $ make -C test SELECTOR=my-filter lisp/emacs-lisp/ert-tests.log
  $ make -C test SELECTOR=my-timer lisp/emacs-lisp/ert-tests.log

(For me, doing everything in one go, e.g., with SELECTOR='"my-.*"',
doesn't complete on master, so the output below is from separate runs.)


Old behavior
============
Prior to fe0f15dbc96 "ert.el: Use `handler-bind` to record backtraces"

SELECTOR=my-baseline

  -*- mode: compilation; default-directory: "~/emacs/handler-bind/test/" -*-
  Compilation started at Thu Feb  1 14:00:41

  make lisp/emacs-lisp/ert-tests.log
    ELC+ELN  lisp/emacs-lisp/ert-tests.elc
    GEN      lisp/emacs-lisp/ert-tests.log
  Running 1 tests (2024-02-01 14:00:45-0800, selector `my-baseline')
  Test my-baseline backtrace:
    error("Done wrong")
    (closure (ert--test-body-was-run t) nil (error "Done wrong") nil)()
    ert--run-test-internal(#s(ert--test-execution-info :test #s(ert-test
    ert-run-test(#s(ert-test :name my-baseline :documentation nil :
    ert-run-or-rerun-test(#s(ert--stats :selector my-baseline :test
    ert-run-tests(my-baseline #f(compiled-function (event-type &res
    ert-run-tests-batch(my-baseline)
    ert-run-tests-batch-and-exit(my-baseline)
    eval((ert-run-tests-batch-and-exit 'my-baseline) t)
    command-line-1(("-L" ":." "-l" "ert" "-l" "lisp/emacs-lisp/ert-tests
    command-line()
    normal-top-level()
  Test my-baseline condition:
      (error "Done wrong")
     FAILED  1/1  my-baseline (0.000469 sec) at lisp/emacs-lisp/ert-tests.el:904

  Ran 1 tests, 0 results as expected, 1 unexpected (2024-02-01 14:00:46-0800, 0.428006 sec)

  1 unexpected results:
     FAILED  my-baseline  "Done wrong"

  make: *** [Makefile:181: lisp/emacs-lisp/ert-tests.log] Error 1

  Compilation exited abnormally with code 2 at Thu Feb  1 14:00:46, duration 4.32 s


SELECTOR=my-filter

  -*- mode: compilation; default-directory: "~/emacs/handler-bind/test/" -*-
  Compilation started at Thu Feb  1 14:03:54

  make lisp/emacs-lisp/ert-tests.log
    ELC+ELN  lisp/emacs-lisp/ert-tests.elc
    GEN      lisp/emacs-lisp/ert-tests.log
  Running 1 tests (2024-02-01 14:03:58-0800, selector `my-filter')
  Test my-filter backtrace:
    error("Encountered bad value")
    (progn (error "Encountered bad value"))
    (if (string-search "42" string) (progn (error "Encountered bad value
    (closure (t) (_ string) (if (string-search "42" string) (progn (erro
    accept-process-output(nil 0.01)
    (while (process-live-p proc) (accept-process-output nil 0.01))
    (progn (while (process-live-p proc) (accept-process-output nil 0.01)
    (unwind-protect (progn (while (process-live-p proc) (accept-process-
    (let* ((-with-timeout-timer- (run-with-timer 5 nil #'(lambda nil (th
    (catch 'timeout (let* ((-with-timeout-timer- (run-with-timer 5 nil #
    (let ((-with-timeout-value- (catch 'timeout (let* ((-with-timeout-ti
    (let ((proc (start-process "my-filter" (current-buffer) "sh" "-c" "f
    (closure (ert--test-body-was-run t) nil (let ((proc (start-process "
    ert--run-test-internal(#s(ert--test-execution-info :test #s(ert-test
    ert-run-test(#s(ert-test :name my-filter :documentation nil :body (c
    ert-run-or-rerun-test(#s(ert--stats :selector my-filter :tests [#s(e
    ert-run-tests(my-filter #f(compiled-function (event-type &rest event
    ert-run-tests-batch(my-filter)
    ert-run-tests-batch-and-exit(my-filter)
    eval((ert-run-tests-batch-and-exit 'my-filter) t)
    command-line-1(("-L" ":." "-l" "ert" "-l" "lisp/emacs-lisp/ert-tests
    command-line()
    normal-top-level()
  Test my-filter condition:
      (error "Encountered bad value")
     FAILED  1/1  my-filter (0.476963 sec) at lisp/emacs-lisp/ert-tests.el:907

  Ran 1 tests, 0 results as expected, 1 unexpected (2024-02-01 14:03:59-0800, 1.204823 sec)

  1 unexpected results:
     FAILED  my-filter  "Encountered bad value"

  make: *** [Makefile:181: lisp/emacs-lisp/ert-tests.log] Error 1

  Compilation exited abnormally with code 2 at Thu Feb  1 14:03:59, duration 5.12 s


SELECTOR=my-timer

  -*- mode: compilation; default-directory: "~/emacs/handler-bind/test/" -*-
  Compilation started at Thu Feb  1 14:04:46

  make lisp/emacs-lisp/ert-tests.log
    GEN      lisp/emacs-lisp/ert-tests.log
  Running 1 tests (2024-02-01 14:04:47-0800, selector `my-timer')
  Test my-timer backtrace:
    error("Encountered a problem")
    (closure (ert--test-body-was-run t) nil (error "Encountered a proble
    apply((closure (ert--test-body-was-run t) nil (error "Encountered a 
    timer-event-handler([t 26044 5504 133541 nil (closure (ert--test-bod
    accept-process-output(nil 5)
    (while (accept-process-output nil 5))
    (progn (while (accept-process-output nil 5)))
    (unwind-protect (progn (while (accept-process-output nil 5))) (cance
    (let* ((-with-timeout-timer- (run-with-timer 5 nil #'(lambda nil (th
    (catch 'timeout (let* ((-with-timeout-timer- (run-with-timer 5 nil #
    (let ((-with-timeout-value- (catch 'timeout (let* ((-with-timeout-ti
    (closure (ert--test-body-was-run t) nil (run-at-time 0.2 nil #'(lamb
    ert--run-test-internal(#s(ert--test-execution-info :test #s(ert-test
    ert-run-test(#s(ert-test :name my-timer :documentation nil :body (cl
    ert-run-or-rerun-test(#s(ert--stats :selector my-timer :tests [#s(er
    ert-run-tests(my-timer #f(compiled-function (event-type &rest event-
    ert-run-tests-batch(my-timer)
    ert-run-tests-batch-and-exit(my-timer)
    eval((ert-run-tests-batch-and-exit 'my-timer) t)
    command-line-1(("-L" ":." "-l" "ert" "-l" "lisp/emacs-lisp/ert-tests
    command-line()
    normal-top-level()
  Test my-timer condition:
      (error "Encountered a problem")
     FAILED  1/1  my-timer (0.201019 sec) at lisp/emacs-lisp/ert-tests.el:919

  Ran 1 tests, 0 results as expected, 1 unexpected (2024-02-01 14:04:48-0800, 0.701159 sec)

  1 unexpected results:
     FAILED  my-timer  "Encountered a problem"

  make: *** [Makefile:181: lisp/emacs-lisp/ert-tests.log] Error 1

  Compilation exited abnormally with code 2 at Thu Feb  1 14:04:48, duration 1.86 s


New behavior
============
HEAD happens to at 71b5d5a9799 "; Fix typos"

SELECTOR=my-baseline

  -*- mode: compilation; default-directory: "~/emacs/master/test/" -*-
  Compilation started at Thu Feb  1 13:54:48

  make lisp/emacs-lisp/ert-tests.log
    ELC+ELN  lisp/emacs-lisp/ert-tests.elc
    GEN      lisp/emacs-lisp/ert-tests.log
  Running 1 tests (2024-02-01 13:54:52-0800, selector `my-baseline')
  Test my-baseline backtrace:
    error("Done wrong")
    (closure (ert--test-body-was-run t) nil (error "Done wrong") nil)()
    #f(compiled-function () #<bytecode 0x6b4b3301354d5f2>)()
    handler-bind-1(#f(compiled-function () #<bytecode 0x6b4b3301354d5f2>
    ert--run-test-internal(#s(ert--test-execution-info :test #s(ert-test
    ert-run-test(#s(ert-test :name my-baseline :documentation nil :
    ert-run-or-rerun-test(#s(ert--stats :selector my-baseline :test
    ert-run-tests(my-baseline #f(compiled-function (event-type &res
    ert-run-tests-batch(my-baseline)
    ert-run-tests-batch-and-exit(my-baseline)
    eval((ert-run-tests-batch-and-exit 'my-baseline) t)
    command-line-1(("-L" ":." "-l" "ert" "-l" "lisp/emacs-lisp/ert-tests
    command-line()
    normal-top-level()
  Test my-baseline condition:
      (error "Done wrong")
     FAILED  1/1  my-baseline (0.000371 sec) at lisp/emacs-lisp/ert-tests.el:879

  Ran 1 tests, 0 results as expected, 1 unexpected (2024-02-01 13:54:52-0800, 0.495511 sec)

  1 unexpected results:
     FAILED  my-baseline  "Done wrong"

  make: *** [Makefile:181: lisp/emacs-lisp/ert-tests.log] Error 1

  Compilation exited abnormally with code 2 at Thu Feb  1 13:54:52, duration 4.49 s


SELECTOR=my-filter

  -*- mode: compilation; default-directory: "~/emacs/master/test/" -*-
  Compilation started at Thu Feb  1 13:55:59

  make lisp/emacs-lisp/ert-tests.log
    GEN      lisp/emacs-lisp/ert-tests.log
  Running 1 tests (2024-02-01 13:56:00-0800, selector `my-filter')
  error in process filter: Encountered bad value
  make: *** [Makefile:181: lisp/emacs-lisp/ert-tests.log] Error 255

  Compilation exited abnormally with code 2 at Thu Feb  1 13:56:01, duration 1.69 s


SELECTOR=my-timer

  Running 1 tests (2024-02-01 13:56:46-0800, selector `my-timer')
  Error running timer: (error "Encountered a problem")
     passed  1/1  my-timer (5.005249 sec)

  Ran 1 tests, 1 results as expected, 0 unexpected (2024-02-01 13:56:51-0800, 5.005712 sec)


I suppose folks who prefer a backtrace can always wrap their filters and
timers in their own `handler-bind' forms, but the premature exit thing
would seem to affect anything that greps the output for well known
indicators, like "FAILED". These might include tests that spawn other
tests and external scripts.

Anyway, thanks a lot for adding this feature. It should prove quite
useful to ERC.

J.P.