command-without-trailing-newline-test test failure

[Apteryks]

Hi,

The GNU Guix CI has found what is probably a non-deterministic (flaky) test: https://ci.guix.gnu.org/build/3324486/log/raw

Here's an excerpt of the failed test suite output:

********************* VERSIONS **************************
GNU Emacs 29.1
ESS 18.10.3snapshot
ESSR 1.8
*********************************************************
make -C lisp all
make[3]: Entering directory '/tmp/guix-build-emacs-ess-18.10.2-1.3691ecc.drv-0/source/lisp'
make[3]: Nothing to be done for 'all'.
make[3]: Leaving directory '/tmp/guix-build-emacs-ess-18.10.2-1.3691ecc.drv-0/source/lisp'
make[2]: Leaving directory '/tmp/guix-build-emacs-ess-18.10.2-1.3691ecc.drv-0/source'
make[2]: Entering directory '/tmp/guix-build-emacs-ess-18.10.2-1.3691ecc.drv-0/source'
make[3]: Entering directory '/tmp/guix-build-emacs-ess-18.10.2-1.3691ecc.drv-0/source/lisp'
make[3]: Nothing to be done for 'julia-mode.el'.
make[3]: Leaving directory '/tmp/guix-build-emacs-ess-18.10.2-1.3691ecc.drv-0/source/lisp'
make[2]: Leaving directory '/tmp/guix-build-emacs-ess-18.10.2-1.3691ecc.drv-0/source'
emacs -Q --script run-tests
Running 185 tests (2024-01-18 15:16:30+0000, selector ‘t’)
   passed    1/185  R-mode (0.021565 sec)
Test command-without-trailing-newline-test backtrace:
  signal(ert-test-failed (((should (string= actual expected)) :form (string= "> \n> " "\n> ") :value nil :explanation (arrays-of-d
  ert-fail(((should (string= actual expected)) :form (string= "> \n> " "\n> ") :value nil :explanation (arrays-of-different-length
  (if (unwind-protect (setq value-210 (apply fn-208 args-209)) (setq form-description-212 (nconc (list '(should (string= actual ex
  (let (form-description-212) (if (unwind-protect (setq value-210 (apply fn-208 args-209)) (setq form-description-212 (nconc (list
  (let ((value-210 'ert-form-evaluation-aborted-211)) (let (form-description-212) (if (unwind-protect (setq value-210 (apply fn-20
  (let* ((fn-208 #'string=) (args-209 (condition-case err (let ((signal-hook-function #'ert--should-signal-hook)) (list actual exp
  (closure (t) (actual expected) (let* ((fn-208 #'string=) (args-209 (condition-case err (let (...) (list actual expected)) (error
  funcall((closure (t) (actual expected) (let* ((fn-208 #'string=) (args-209 (condition-case err (let (...) (list actual expected)
  (progn (etest--wait-for-inferior) (funcall do-result (etest--result etest-local-inferior-buffer t) value))
  (unwind-protect (progn (etest--wait-for-inferior) (funcall do-result (etest--result etest-local-inferior-buffer t) value)) (etes
  etest--flush-inferior-buffer((closure (t) (actual expected) (let* ((fn-208 #'string=) (args-209 (condition-case err (let (...) (
  (let nil (etest--flush-inferior-buffer do-result etest--value))
  (cond ((eq etest--key :inf-buffer) (let nil (setq etest-local-inferior-buffer (eval etest--value t)))) ((eq etest--key :cleanup)
  (let ((etest--key (car-safe (prog1 body (setq body (cdr body))))) (etest--value (car-safe (prog1 body (setq body (cdr body))))))
  (if (keywordp (car body)) (let ((etest--key (car-safe (prog1 body (setq body (cdr body))))) (etest--value (car-safe (prog1 body 
  (while body (if (keywordp (car body)) (let ((etest--key (car-safe (prog1 body (setq body ...)))) (etest--value (car-safe (prog1 
  (unwind-protect (while body (if (keywordp (car body)) (let ((etest--key (car-safe (prog1 body ...))) (etest--value (car-safe (pr
  (let ((etest--msg-sentinel (etest--make-message-sentinel)) (etest--last-case "") etest--cleanup) (unwind-protect (while body (if
  (save-current-buffer (set-buffer etest--buf) (let ((etest--msg-sentinel (etest--make-message-sentinel)) (etest--last-case "") et
  (unwind-protect (save-current-buffer (set-buffer etest--buf) (let ((etest--msg-sentinel (etest--make-message-sentinel)) (etest--
  (let ((etest--buf (etest--new-buffer (progn (if (eq (car body) :config) (progn (car-safe ...) (setq body ...))) (let (local) (wh
  etest--run-test((:init ((mode . r) (ess-offset . 4) (eval progn (ess-test-r-set-local-process) (ess-set-style 'RRR 'quiet) (setq
  (closure (t) nil (etest--run-test '(:init ((mode . r) (ess-offset . 4) (eval progn (ess-test-r-set-local-process) (ess-set-style
  ert--run-test-internal(#s(ert--test-execution-info :test #s(ert-test :name command-without-trailing-newline-test :documentation 
  ert-run-test(#s(ert-test :name command-without-trailing-newline-test :documentation "It is a bug when a command doesn..." :body 
  ert-run-or-rerun-test(#s(ert--stats :selector t :tests ... :test-map #<hash-table eql 185/185 0x4620ae9> :test-results ... :test
  ert-run-tests(t #f(compiled-function (event-type &rest event-args) #<bytecode -0x1040a196866395cf>) nil)
  ert-run-tests-batch(t)
  ert-run-tests-batch-and-exit(t)
  eval-buffer(#<buffer  *load*> nil "/tmp/guix-build-emacs-ess-18.10.2-1.3691ecc.drv-0/..." nil t)  ; Reading at buffer position 2
  #f(compiled-function (buffer file) #<bytecode 0x79df5fdd5ed03af>)(#<buffer  *load*> "/tmp/guix-build-emacs-ess-18.10.2-1.3691ecc
  load-with-code-conversion("/tmp/guix-build-emacs-ess-18.10.2-1.3691ecc.drv-0/..." "/tmp/guix-build-emacs-ess-18.10.2-1.3691ecc.d
  command-line--load-script("/tmp/guix-build-emacs-ess-18.10.2-1.3691ecc.drv-0/...")
  command-line-1(("-scriptload" "run-tests"))
  command-line()
  normal-top-level()
Test command-without-trailing-newline-test condition:
    (ert-test-failed
     ((should
       (string= actual expected))
      :form
      (string= "> \n> " "\n> ")
      :value nil :explanation
      (arrays-of-different-length 5 3 "> \n> " "\n> " first-mismatch-at 0)))
   FAILED    2/185  command-without-trailing-newline-test (0.102884 sec) at ess-test-inf.el:326

[Apteryks]

Looking at the GNU Guix package definition, there appear to be many more tests that are disabled/skipped due to failures:

(disable-tests (list "test/ess-test-inf.el"
                                         "test/ess-test-r.el")
                                   ("ess--derive-connection-path"
                                    "ess-eval-line-test"
                                    "ess-eval-region-test"
                                    "ess-mock-remote-process"
                                    "ess-r-load-ESSR-github-fetch-no"
                                    "ess-r-load-ESSR-github-fetch-yes"
                                    "ess-set-working-directory-test"
                                    "ess-test-r-startup-directory"))
                    (disable-etests "test/ess-test-r-eval.el"
                                    ("ess-r-eval-ns-env-roxy-tracebug-test"
                                     "ess-r-eval-sink-freeze-test"))
                    (disable-etests
                     "test/ess-test-inf.el"
                     ("command-without-trailing-newline-test"))

To easily reproduce them, editing out the 'skip-failing-tests' of the emacs-ess and building the package with this modification should show the failures. Attached is a build log:

y99wvkm6qj7yr0y9qq0hfrsz99nh68vk-emacs-ess-18.10.2-1.3691ecc.drv.txt

[mmaechler]

Thank you @Apteryks ; Could we (ESS core) get help on this? IIUC, our test expert (@lionel- ) is currently mostly busy with other jobs.
Where do you think we should consider fixing issues in ESS ?

[lionel-]

It's unlikely we'll get around to fixing that soon so I guess the best course of action is to add the test to your skip list.

[Apteryks]

That's how it's currently handled in GNU Guix; thanks!

[Apteryks]

I'm sharing here a new failure, possible triggered by a system under high load (timeouts too short?), but I'm just speculating:

1 unexpected results:
   FAILED  ess--command-browser-timeout-test

The full output (see: 1 unexpected results:
FAILED ess--command-browser-timeout-test) looks like:

starting phase `check'
********************* VERSIONS **************************
GNU Emacs 29.2
ESS 18.10.3snapshot
ESSR 1.8
*********************************************************
make -C test all
make[1]: Entering directory '/tmp/guix-build-emacs-ess-18.10.2-1.3691ecc.drv-0/source/test'
make[2]: Entering directory '/tmp/guix-build-emacs-ess-18.10.2-1.3691ecc.drv-0/source'
********************* VERSIONS **************************
GNU Emacs 29.2
ESS 18.10.3snapshot
ESSR 1.8
*********************************************************
make -C lisp all
make[3]: Entering directory '/tmp/guix-build-emacs-ess-18.10.2-1.3691ecc.drv-0/source/lisp'
make[3]: Nothing to be done for 'all'.
make[3]: Leaving directory '/tmp/guix-build-emacs-ess-18.10.2-1.3691ecc.drv-0/source/lisp'
make[2]: Leaving directory '/tmp/guix-build-emacs-ess-18.10.2-1.3691ecc.drv-0/source'
make[2]: Entering directory '/tmp/guix-build-emacs-ess-18.10.2-1.3691ecc.drv-0/source'
make[3]: Entering directory '/tmp/guix-build-emacs-ess-18.10.2-1.3691ecc.drv-0/source/lisp'
make[3]: Nothing to be done for 'julia-mode.el'.
make[3]: Leaving directory '/tmp/guix-build-emacs-ess-18.10.2-1.3691ecc.drv-0/source/lisp'
make[2]: Leaving directory '/tmp/guix-build-emacs-ess-18.10.2-1.3691ecc.drv-0/source'
emacs -Q --script run-tests
Running 184 tests (2024-01-21 15:09:40+0000, selector ‘t’)
   passed    1/184  R-mode (0.004265 sec)
Test ess--command-browser-timeout-test backtrace:
  signal(ert-test-failed (((should (inferior-ess-available-p)) :form (inferior-ess-available-p) :value nil)))
  ert-fail(((should (inferior-ess-available-p)) :form (inferior-ess-available-p) :value nil))
  (if (unwind-protect (setq value-1608 (apply fn-1606 args-1607)) (setq form-description-1610 (nconc (list '(should (inferior-ess-
  (unless (unwind-protect (setq value-1608 (apply fn-1606 args-1607)) (setq form-description-1610 (nconc (list '(should (inferior-
  (let (form-description-1610) (unless (unwind-protect (setq value-1608 (apply fn-1606 args-1607)) (setq form-description-1610 (nc
  (let ((value-1608 'ert-form-evaluation-aborted-1609)) (let (form-description-1610) (unless (unwind-protect (setq value-1608 (app
  (let* ((fn-1606 #'inferior-ess-available-p) (args-1607 (condition-case err (let ((signal-hook-function #'ert--should-signal-hook
  (should (inferior-ess-available-p))
  eval((should (inferior-ess-available-p)) t)
  (let ((inhibit-message t)) (eval x t))
  (cond ((equal x '(kbd "C-u")) (setq current-prefix-arg (list 4))) ((stringp x) (if (string= x "C-u") (setq current-prefix-arg (l
  (closure (t) (x) (cond ((equal x '(kbd "C-u")) (setq current-prefix-arg (list 4))) ((stringp x) (if (string= x "C-u") (setq curr
  mapc((closure (t) (x) (cond ((equal x '(kbd "C-u")) (setq current-prefix-arg (list 4))) ((stringp x) (if (string= x "C-u") (setq
  (let ((cursor (car tail))) (goto-char cursor) (setq last-command current-lc) (setq current-prefix-arg current-cpa) (mapc #'(lamb
  (while tail (let ((cursor (car tail))) (goto-char cursor) (setq last-command current-lc) (setq current-prefix-arg current-cpa) (
  (let ((tail cursors-start)) (while tail (let ((cursor (car tail))) (goto-char cursor) (setq last-command current-lc) (setq curre
  (let ((current-lc last-command) (current-cpa current-prefix-arg)) (let ((tail cursors-start)) (while tail (let ((cursor (car tai
  (let (cursors-start cursors-end) (while (search-backward "¶" nil t) (delete-char 1) (let ((marker (point-marker))) (set-marker-i
  (save-current-buffer (set-buffer buf) (goto-char (point-min)) (if (search-forward "×" nil t) (progn (backward-delete-char 1) (se
  etest-run(#<killed buffer> ((should (inferior-ess-available-p))))
  (if (keywordp (car body)) (let ((etest--key (car-safe (prog1 body (setq body (cdr body))))) (etest--value (car-safe (prog1 body 
  (while body (if (keywordp (car body)) (let ((etest--key (car-safe (prog1 body (setq body ...)))) (etest--value (car-safe (prog1 
  (unwind-protect (while body (if (keywordp (car body)) (let ((etest--key (car-safe (prog1 body ...))) (etest--value (car-safe (pr
  (let ((etest--msg-sentinel (etest--make-message-sentinel)) (etest--last-case "") etest--cleanup) (unwind-protect (while body (if
  (save-current-buffer (set-buffer etest--buf) (let ((etest--msg-sentinel (etest--make-message-sentinel)) (etest--last-case "") et
  (unwind-protect (save-current-buffer (set-buffer etest--buf) (let ((etest--msg-sentinel (etest--make-message-sentinel)) (etest--
  (let ((etest--buf (etest--new-buffer (progn (if (eq (car body) :config) (progn (car-safe ...) (setq body ...))) (let (local) (wh
  etest--run-test((:init ((mode . r) (ess-offset . 4) (eval progn (ess-test-r-set-local-process) (ess-set-style 'RRR 'quiet) (setq
  (closure (t) nil (etest--run-test '(:init ((mode . r) (ess-offset . 4) (eval progn (ess-test-r-set-local-process) (ess-set-style
  ert--run-test-internal(#s(ert--test-execution-info :test #s(ert-test :name ess--command-browser-timeout-test :documentation "`es
  ert-run-test(#s(ert-test :name ess--command-browser-timeout-test :documentation "`ess-command' fails with hanging..." :body (clo
  ert-run-or-rerun-test(#s(ert--stats :selector t :tests ... :test-map #<hash-table eql 184/184 0x4625845> :test-results ... :test
  ert-run-tests(t #f(compiled-function (event-type &rest event-args) #<bytecode -0x1040af7192a7fb4f>) nil)
  ert-run-tests-batch(t)
  ert-run-tests-batch-and-exit(t)
  eval-buffer(#<buffer  *load*> nil "/tmp/guix-build-emacs-ess-18.10.2-1.3691ecc.drv-0/..." nil t)  ; Reading at buffer position 2
  #f(compiled-function (buffer file) #<bytecode 0x79df5fdd582c3af>)(#<buffer  *load*> "/tmp/guix-build-emacs-ess-18.10.2-1.3691ecc
  load-with-code-conversion("/tmp/guix-build-emacs-ess-18.10.2-1.3691ecc.drv-0/..." "/tmp/guix-build-emacs-ess-18.10.2-1.3691ecc.d
  command-line--load-script("/tmp/guix-build-emacs-ess-18.10.2-1.3691ecc.drv-0/...")
  command-line-1(("-scriptload" "run-tests"))
  command-line()
  normal-top-level()
Test ess--command-browser-timeout-test condition:
    (ert-test-failed
     ((should
       (inferior-ess-available-p))
      :form
      (inferior-ess-available-p)
      :value nil))
   FAILED    2/184  ess--command-browser-timeout-test (0.045122 sec) at ess-test-inf.el:147