GNU bug report logs - #59103
29.0.50; esh-var-tests intermittently fails on macOS 12.6.1

Previous Next

To add a comment to this bug, you must first unarchive it, by sending
a message to control AT debbugs.gnu.org, with unarchive 59103 in the body.
You can then email your comments to 59103 AT debbugs.gnu.org in the normal way.

Toggle the display of automated, internal messages from the tracker.

Message #5 received at submit <at> debbugs.gnu.org (full text, mbox):

From: Stefan Kangas <stefankangas <at> gmail.com>
To: bug-gnu-emacs <bug-gnu-emacs <at> gnu.org>
Subject: 29.0.50; esh-var-tests intermittently fails on macOS 12.6.1
Date: Mon, 7 Nov 2022 12:09:46 +0100

X-Debbugs-CC: Jim Porter <jporterbugs <at> gmail.com>

Intermittently failing test on macOS 12.6.1, see below output from
"make -j5 check":

Test esh-var-test/interp-cmd-external-indices backtrace:
  signal(error ("Index exceeds length of list"))
  error("Index exceeds length of list")
  eshell-index-value(nil #("1" 0 1 (number t)))
  eshell-apply-indices(nil ((#("1" 0 1 (number t)))) nil)
  eval((eshell-apply-indices 'nil '((#("1" 0 1 (number t)))) 'nil))
  eshell-do-eval((eshell-apply-indices 'nil '((#("1" 0 1 (number t))))
  #f(compiled-function () #<bytecode -0x121eee2dc2a0f5da>)()
  funcall(#f(compiled-function () #<bytecode -0x121eee2dc2a0f5da>))
  (let ((indices '((#("1" 0 1 (number t)))))) (funcall '#f(compiled-fu
  eval((let ((indices '((#("1" 0 1 ...))))) (funcall '#f(compiled-func
  eshell-do-eval((let ((indices '((#("1" 0 1 ...))))) (eshell-apply-in
  eshell-do-eval((eshell-escape-arg (let ((indices '((...)))) (eshell-
  eshell-do-eval((list (eshell-escape-arg (let ((indices '(...))) (esh
  eshell-do-eval((eshell-named-command '"echo" (list (eshell-escape-ar
  eshell-do-eval((prog1 (eshell-named-command '"echo" (list (eshell-es
  (condition-case err (eshell-do-eval '(prog1 (eshell-named-command '"
  eval((condition-case err (eshell-do-eval '(prog1 (eshell-named-comma
  eshell-do-eval((condition-case err (eshell-do-eval '(prog1 (eshell-n
  #f(compiled-function () #<bytecode -0x121eee2dc2a0f5da>)()
  funcall(#f(compiled-function () #<bytecode -0x121eee2dc2a0f5da>))
  (let ((eshell-this-command-hook '(ignore))) (funcall '#f(compiled-fu
  eval((let ((eshell-this-command-hook '(ignore))) (funcall '#f(compil
  eshell-do-eval((let ((eshell-this-command-hook '(ignore))) (conditio
  eshell-do-eval((progn (let ((eshell-this-command-hook '(ignore))) (c
  (catch 'top-level (eshell-do-eval '(progn (let ((eshell-this-command
  eval((catch 'top-level (eshell-do-eval '(progn (let ((eshell-this-co
  eshell-do-eval((catch 'top-level (eshell-do-eval '(progn (let ((eshe
  eshell-do-eval((progn 'nil (catch 'top-level (eshell-do-eval '(progn
  #f(compiled-function () #<bytecode -0x121eee2dc2a0f5da>)()
  funcall(#f(compiled-function () #<bytecode -0x121eee2dc2a0f5da>))
  (let ((eshell-current-handles '[nil (t . 1) (t . 1)]) (eshell-curren
  eval((let ((eshell-current-handles '[nil (t . 1) (t . 1)]) (eshell-c
  eshell-do-eval((let ((eshell-current-handles '[nil (t . 1) (t . 1)])
  eshell-resume-eval()
  eshell-resume-command(#<process echo> "finished\n")
  run-hook-with-args(eshell-resume-command #<process echo> "finished\n
  eshell-kill-process-function(#<process echo> "finished\n")
  #f(compiled-function () #<bytecode 0xc5a98ae27b3455a>)()
  eshell-sentinel(#<process echo> "finished\n")
  sleep-for(0.1)
  sit-for(0.1)
  eshell-wait-for-subprocess()
  eshell-match-command-output("echo ${*echo \"hi\nbye\"}[1]" "bye\n")
  #f(compiled-function () #<bytecode -0x14786256247f0408>)()
  ert--run-test-internal(#s(ert--test-execution-info :test #s(ert-test
  ert-run-test(#s(ert-test :name esh-var-test/interp-cmd-external-indi
  ert-run-or-rerun-test(#s(ert--stats :selector ... :tests ... :test-m
  ert-run-tests((not (or (tag :expensive-test) (tag :unstable) (tag :n
  ert-run-tests-batch((not (or (tag :expensive-test) (tag :unstable) (
  ert-run-tests-batch-and-exit((not (or (tag :expensive-test) (tag :un
  eval((ert-run-tests-batch-and-exit '(not (or (tag :expensive-test) (
  command-line-1(("-L" ":." "-l" "ert" "-l" "lisp/eshell/esh-var-tests
  command-line()
  normal-top-level()
Test esh-var-test/interp-cmd-external-indices condition:
    (error "Index exceeds length of list")
   FAILED  15/85  esh-var-test/interp-cmd-external-indices (0.620384
sec) at lisp/eshell/esh-var-tests.el:157

Test esh-var-test/interp-concat-cmd backtrace:
  signal(ert-test-failed (((should (eshell-command-result--equal comma
  ert-fail(((should (eshell-command-result--equal command (eshell-test
  eshell-command-result-equal("echo ${*echo \"1\n2\"}3" (1 23))
  #f(compiled-function () #<bytecode 0x11cb13a1ddea0c78>)()
  ert--run-test-internal(#s(ert--test-execution-info :test #s(ert-test
  ert-run-test(#s(ert-test :name esh-var-test/interp-concat-cmd :docum
  ert-run-or-rerun-test(#s(ert--stats :selector ... :tests ... :test-m
  ert-run-tests((not (or (tag :expensive-test) (tag :unstable) (tag :n
  ert-run-tests-batch((not (or (tag :expensive-test) (tag :unstable) (
  ert-run-tests-batch-and-exit((not (or (tag :expensive-test) (tag :un
  eval((ert-run-tests-batch-and-exit '(not (or (tag :expensive-test) (
  command-line-1(("-L" ":." "-l" "ert" "-l" "lisp/eshell/esh-var-tests
  command-line()
  normal-top-level()
Test esh-var-test/interp-concat-cmd condition:
    (ert-test-failed
     ((should
       (eshell-command-result--equal command
                     (eshell-test-command-result command)
                     result))
      :form
      (eshell-command-result--equal "echo ${*echo \"1\n2\"}3" "3"
                    (1 23))
      :value nil :explanation
      (nonequal-result
       (command "echo ${*echo \"1\n2\"}3")
       (result "3")
       (expected
    (1 23)))))
   FAILED  17/85  esh-var-test/interp-concat-cmd (0.754070 sec) at
lisp/eshell/esh-var-tests.el:176

They do not fail every time: sometimes neither fails, sometimes one
does and sometimes the other.  Only once did both fail at the same
time, after several runs of "make check".

I have been unable to reproduce these failures using "make -C test
esh-var-tests".

I also cannot reproduce this manually in emacs -Q:

Welcome to the Emacs shell

~/wip/emacs $ echo ${*echo "hi
bye"}[1]
bye
~/wip/emacs $ echo ${*echo "1
2"}3
(1 23)
~/wip/emacs $

In GNU Emacs 29.0.50 (build 1, x86_64-apple-darwin21.6.0, NS
 appkit-2113.60 Version 12.6.1 (Build 21G217)) of 2022-11-07 built on
 SK-MacBook-Pro
Repository revision: 236703ca05382c9cdf4ce6a2dd2b3244c20d564d
Repository branch: master
Windowing system distributor 'Apple', version 10.3.2113
System Description:  macOS 12.6.1

Configured features:
ACL GIF GMP GNUTLS JPEG JSON LCMS2 LIBXML2 MODULES NOTIFY KQUEUE NS
PDUMPER PNG SQLITE3 THREADS TIFF TOOLKIT_SCROLL_BARS WEBP XIM ZLIB

Important settings:
  value of $LC_CTYPE: UTF-8
  locale-coding-system: utf-8-unix

Major mode: Lisp Interaction

Minor modes in effect:
  tooltip-mode: t
  global-eldoc-mode: t
  eldoc-mode: t
  show-paren-mode: t
  electric-indent-mode: t
  mouse-wheel-mode: t
  tool-bar-mode: t
  menu-bar-mode: t
  file-name-shadow-mode: t
  global-font-lock-mode: t
  font-lock-mode: t
  blink-cursor-mode: t
  line-number-mode: t
  indent-tabs-mode: t
  transient-mark-mode: t
  auto-composition-mode: t
  auto-encryption-mode: t
  auto-compression-mode: t

Load-path shadows:
None found.

Features:
(shadow sort mail-extr emacsbug message mailcap yank-media puny dired
dired-loaddefs rfc822 mml mml-sec password-cache epa derived epg rfc6068
epg-config gnus-util text-property-search time-date subr-x mm-decode
mm-bodies mm-encode mail-parse rfc2231 mailabbrev gmm-utils mailheader
cl-loaddefs cl-lib sendmail rfc2047 rfc2045 ietf-drums mm-util
mail-prsvr mail-utils rmc iso-transl tooltip cconv eldoc paren electric
uniquify ediff-hook vc-hooks lisp-float-type elisp-mode mwheel
term/ns-win ns-win ucs-normalize mule-util term/common-win tool-bar dnd
fontset image regexp-opt fringe tabulated-list replace newcomment
text-mode lisp-mode prog-mode register page tab-bar menu-bar rfn-eshadow
isearch easymenu timer select scroll-bar mouse jit-lock font-lock syntax
font-core term/tty-colors frame minibuffer nadvice seq simple cl-generic
indonesian philippine 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 emoji-zwj charscript charprop case-table epa-hook
jka-cmpr-hook help abbrev obarray oclosure cl-preloaded button loaddefs
theme-loaddefs faces cus-face macroexp files window text-properties
overlay sha1 md5 base64 format env code-pages mule custom widget keymap
hashtable-print-readable backquote threads kqueue cocoa ns lcms2
multi-tty make-network-process emacs)

Memory information:
((conses 16 35812 6611)
 (symbols 48 5009 0)
 (strings 32 12556 1611)
 (string-bytes 1 351138)
 (vectors 16 9320)
 (vector-slots 8 146142 8539)
 (floats 8 21 23)
 (intervals 56 198 0)
 (buffers 984 10))

Message #8 received at 59103 <at> debbugs.gnu.org (full text, mbox):

From: Jim Porter <jporterbugs <at> gmail.com>
To: Stefan Kangas <stefankangas <at> gmail.com>, 59103 <at> debbugs.gnu.org
Subject: Re: bug#59103: 29.0.50; esh-var-tests intermittently fails on macOS
 12.6.1
Date: Mon, 7 Nov 2022 21:39:57 -0800

On 11/7/2022 3:09 AM, Stefan Kangas wrote:
> Intermittently failing test on macOS 12.6.1, see below output from
> "make -j5 check":
> 
[snip]
> They do not fail every time: sometimes neither fails, sometimes one
> does and sometimes the other.  Only once did both fail at the same
> time, after several runs of "make check".

Both of these failures look like the ${subcommand} didn't see any output 
by the time Eshell expanded it into the top-level command. My guess is 
that something is going awry in 'eshell-sentinel'. I haven't been able 
to reproduce this locally (on a GNU/Linux system), but since it seems 
you *can* reproduce it, you could try the following:

1. Check if 'eshell-output-object' ever gets called from within 
'eshell-sentinel' or from the 'finish-io' timer defined there

2. If so, try moving the 'eshell-kill-process-function' call at the end 
of 'eshell-sentinel' (and maybe the 'when-let' block immediately above 
it) inside 'finish-io'

My reasoning here is that I think 'eshell-kill-process-function' is what 
will signal to the rest of Eshell that the process is done, but if the 
process still has output pending (i.e. 'finish-io' gets called from a 
timer to do its thing), then that pending output would get lost.

Hopefully that at least points you in the right direction...

Message #11 received at 59103 <at> debbugs.gnu.org (full text, mbox):

From: Jim Porter <jporterbugs <at> gmail.com>
To: Stefan Kangas <stefankangas <at> gmail.com>, 59103 <at> debbugs.gnu.org
Subject: Re: bug#59103: 29.0.50; esh-var-tests intermittently fails on macOS
 12.6.1
Date: Fri, 9 Dec 2022 23:14:18 -0800

[Message part 1 (text/plain, inline)]

On 11/7/2022 9:39 PM, Jim Porter wrote:
> On 11/7/2022 3:09 AM, Stefan Kangas wrote:
>> Intermittently failing test on macOS 12.6.1, see below output from
>> "make -j5 check":
>>
> [snip]
>> They do not fail every time: sometimes neither fails, sometimes one
>> does and sometimes the other.  Only once did both fail at the same
>> time, after several runs of "make check".

I'm not sure how reliably you can reproduce this, but does the attached 
patch help?

[0001-Fix-a-race-condition-in-Eshell-s-external-process-ma.patch (text/plain, attachment)]

Message #16 received at 59103-done <at> debbugs.gnu.org (full text, mbox):

From: Jim Porter <jporterbugs <at> gmail.com>
To: Stefan Kangas <stefankangas <at> gmail.com>, 59103-done <at> debbugs.gnu.org
Subject: Re: bug#59103: 29.0.50; esh-var-tests intermittently fails on macOS
 12.6.1
Date: Sun, 27 Aug 2023 12:34:46 -0700

On 12/9/2022 11:14 PM, Jim Porter wrote:
> On 11/7/2022 9:39 PM, Jim Porter wrote:
>> On 11/7/2022 3:09 AM, Stefan Kangas wrote:
>>> Intermittently failing test on macOS 12.6.1, see below output from
>>> "make -j5 check":
>>>
>> [snip]
>>> They do not fail every time: sometimes neither fails, sometimes one
>>> does and sometimes the other.  Only once did both fail at the same
>>> time, after several runs of "make check".
> 
> I'm not sure how reliably you can reproduce this, but does the attached 
> patch help?

Pushed now to master as 2efb8d2e244. Hopefully this helps fix things.

Message #19 received at 59103-done <at> debbugs.gnu.org (full text, mbox):

From: Stefan Kangas <stefankangas <at> gmail.com>
To: Jim Porter <jporterbugs <at> gmail.com>
Cc: 59103-done <at> debbugs.gnu.org
Subject: Re: bug#59103: 29.0.50;
 esh-var-tests intermittently fails on macOS 12.6.1
Date: Sun, 27 Aug 2023 21:51:10 +0200

Jim Porter <jporterbugs <at> gmail.com> writes:

> Pushed now to master as 2efb8d2e244. Hopefully this helps fix things.

Sorry, it seems like I dropped the ball here.  Thank you for the fix.

Previous Next

GNU bug tracking system
Copyright (C) 1999 Darren O. Benham, 1997,2003 nCipher Corporation Ltd, 1994-97 Ian Jackson.