Package: emacs;
Reported by: Stefan Monnier <monnier <at> iro.umontreal.ca>
Date: Sun, 17 Dec 2023 00:38:02 UTC
Severity: normal
Found in version 30.0.50
Done: Stefan Monnier <monnier <at> iro.umontreal.ca>
Bug is archived. No further changes may be made.
Message #38 received at 67862 <at> debbugs.gnu.org (full text, mbox):
From: "J.P." <jp <at> neverwas.me> To: Stefan Monnier <monnier <at> iro.umontreal.ca> Cc: 67862 <at> debbugs.gnu.org, Christian Ohler <ohler <at> gnu.org> Subject: Re: bug#67862: 30.0.50; Handler-bind and ert-test-error-debug Date: Thu, 01 Feb 2024 14:27:23 -0800
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.
GNU bug tracking system
Copyright (C) 1999 Darren O. Benham,
1997,2003 nCipher Corporation Ltd,
1994-97 Ian Jackson.