bug#59103: 29.0.50; esh-var-tests intermittently fails on macOS 12.6.1

bug#59103: 29.0.50; esh-var-tests intermittently fails on macOS 12.6.1

[Stefan Kangas]

X-Debbugs-CC: Jim Porter <jporterbugs@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))

bug#59103: 29.0.50; esh-var-tests intermittently fails on macOS 12.6.1

[Jim Porter]

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...

bug#59103: 29.0.50; esh-var-tests intermittently fails on macOS 12.6.1

[Jim Porter]

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

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?

[-- Attachment #2: 0001-Fix-a-race-condition-in-Eshell-s-external-process-ma.patch --]
[-- Type: text/plain, Size: 1528 bytes --]

From 94fe9f56748ac8a73b313df80c666dd020a5d46c Mon Sep 17 00:00:00 2001
From: Jim Porter <jporterbugs@gmail.com>
Date: Fri, 9 Dec 2022 23:07:19 -0800
Subject: [PATCH] Fix a race condition in Eshell's external process management

If a process is busy writing output when 'eshell-sentinel' is called,
it might take a bit of time to finish up.  Don't call
'eshell-kill-process-function' until we're really finished
(bug#59103).

* lisp/eshell/esh-proc.el (eshell-sentinel): Call
'eshell-kill-process-function' in 'finish-io'.
---
 lisp/eshell/esh-proc.el | 6 +++---
 1 file changed, 3 insertions(+), 3 deletions(-)

diff --git a/lisp/eshell/esh-proc.el b/lisp/eshell/esh-proc.el
index 950922ea7f8..199ed3cc622 100644
--- a/lisp/eshell/esh-proc.el
+++ b/lisp/eshell/esh-proc.el
@@ -473,11 +473,11 @@ eshell-sentinel
                             (eshell-close-handles
                              status
                              (when status (list 'quote (= status 0)))
-                             handles)))))
+                             handles)
+                            (eshell-kill-process-function proc string)))))
                 (funcall finish-io))))
         (when-let ((entry (assq proc eshell-process-list)))
-          (eshell-remove-process-entry entry))
-        (eshell-kill-process-function proc string)))))
+          (eshell-remove-process-entry entry))))))
 
 (defun eshell-process-interact (func &optional all query)
   "Interact with a process, using PROMPT if more than one, via FUNC.
-- 
2.25.1

bug#59103: 29.0.50; esh-var-tests intermittently fails on macOS 12.6.1

[Jim Porter]

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.

bug#59103: 29.0.50; esh-var-tests intermittently fails on macOS 12.6.1

[Stefan Kangas]

Jim Porter <jporterbugs@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.