bug#65602: 30.0.50; eshell-test/{elisp,subcommand}-reset-in-pipeline fails intermittently on macOS

bug#65602: 30.0.50; eshell-test/{elisp,subcommand}-reset-in-pipeline fails intermittently on macOS

[Stefan Kangas]

X-Debbugs-CC: jporterbugs@gmail.com

Please find below two more intermittent test failures on macOS.  I
chose to report it separately in the hope that it would make it easier
for you to track, but please merge with one or both of the other bug
reports if it makes more sense.

   passed   1/18  eshell-test/command-running-p (0.067725 sec)
[echo]+ Done (/bin/echo hi)
   passed   2/18  eshell-test/eshell-command/background (0.174720 sec)
[echo]+ Done (/bin/echo hi)
[cat]+ Done (/bin/cat)
   passed   3/18  eshell-test/eshell-command/background-pipeline (0.134142 sec)
   passed   4/18  eshell-test/eshell-command/pipeline (0.074275 sec)
   passed   5/18  eshell-test/eshell-command/simple (0.060042 sec)
   passed   6/18  eshell-test/flush-output (0.003668 sec)
   passed   7/18  eshell-test/forward-arg (0.001930 sec)
   passed   8/18  eshell-test/get-old-input (0.001804 sec)
   passed   9/18  eshell-test/get-old-input/rerun-command (0.012261 sec)
   passed  10/18  eshell-test/get-old-input/run-output (0.007978 sec)
Test eshell-test/lisp-reset-in-pipeline 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 (format \"%s\" eshell-in-pipeline-
  #f(compiled-function () #<bytecode 0xaa4ecd674724b29>)()
  ert--run-test-internal(#s(ert--test-execution-info :test #s(ert-test
  ert-run-test(#s(ert-test :name eshell-test/lisp-reset-in-pipeline :d
  ert-run-or-rerun-test(#s(ert--stats :selector (not ...) :tests [...
  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/eshell-tests"
  command-line()
  normal-top-level()
Test eshell-test/lisp-reset-in-pipeline condition:
    (ert-test-failed
     ((should
       (eshell-command-result--equal command
                     (eshell-test-command-result command)
                     result))
      :form
      (eshell-command-result--equal
       "echo (format \"%s\" eshell-in-pipeline-p) | *cat" nil "nil")
      :value nil :explanation
      (nonequal-result
       (command "echo (format \"%s\" eshell-in-pipeline-p) | *cat")
       (result nil) (expected "nil"))))
   FAILED  11/18  eshell-test/lisp-reset-in-pipeline (0.014149 sec) at
lisp/eshell/eshell-tests.el:101
   passed  12/18  eshell-test/pipe-headproc (0.119374 sec)
   passed  13/18  eshell-test/pipe-headproc-stdin (0.737941 sec)
   passed  14/18  eshell-test/pipe-subcommand (0.118841 sec)
   passed  15/18  eshell-test/pipe-subcommand-with-pipe (0.138578 sec)
   passed  16/18  eshell-test/pipe-tailproc (0.115676 sec)
   passed  17/18  eshell-test/queue-input (1.032341 sec)
Test eshell-test/subcommand-reset-in-pipeline 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 | echo $eshell-in-pipeline-p
  #f(compiled-function () #<bytecode 0x1a44586e0e96bde8>)()
  ert--run-test-internal(#s(ert--test-execution-info :test #s(ert-test
  ert-run-test(#s(ert-test :name eshell-test/subcommand-reset-in-pipel
  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/eshell-tests"
  command-line()
  normal-top-level()
Test eshell-test/subcommand-reset-in-pipeline condition:
    (ert-test-failed
     ((should
       (eshell-command-result--equal command
                     (eshell-test-command-result command)
                     result))
      :form
      (eshell-command-result--equal
       "echo {echo | echo $eshell-in-pipeline-p} | *cat" nil "last")
      :value nil :explanation
      (nonequal-result
       (command "echo {echo | echo $eshell-in-pipeline-p} | *cat")
       (result nil) (expected "last"))))
   FAILED  18/18  eshell-test/subcommand-reset-in-pipeline (0.179328
sec) at lisp/eshell/eshell-tests.el:82

Ran 18 tests, 16 results as expected, 2 unexpected (2023-08-29
20:58:56+0200, 3.768912 sec)

2 unexpected results:
   FAILED  eshell-test/lisp-reset-in-pipeline
   FAILED  eshell-test/subcommand-reset-in-pipeline

make[3]: *** [lisp/eshell/eshell-tests.log] Error 1

In GNU Emacs 30.0.50 (build 2, x86_64-apple-darwin21.6.0, NS
 appkit-2113.60 Version 12.6.8 (Build 21G725)) of 2023-08-28 built on
 MY-MacBook-Pro.local
Repository revision: 7a55d7e8684c02551feb17168047c9
192478e5a0
Repository branch: master
Windowing system distributor 'Apple', version 10.3.2113
System Description:  macOS 12.6.8

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

Important settings:
  value of $LC_COLLATE: C
  value of $LC_CTYPE: sv_SE.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 touch-screen
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 36151 9219) (symbols 48 5093 0) (strings 32 12636 1004)
 (string-bytes 1 352850) (vectors 16 9370)
 (vector-slots 8 147689 12388) (floats 8 21 23) (intervals 56 202 0)
 (buffers 992 10))

bug#65602: 30.0.50; eshell-test/{elisp,subcommand}-reset-in-pipeline fails intermittently on macOS

[Stefan Kangas]

Stefan Kangas <stefankangas@gmail.com> writes:

> I spoke too soon, as I'm now seeing the below two failures.
>
>    FAILED   42/110  esh-var-test/interp-var-indices-subcommand (0.787189 sec) at lisp/eshell/esh-var-tests.el:184
>
>    FAILED   5/11  eshell-test/eshell-command/simple (0.670351 sec) at lisp/eshell/eshell-tests.el:41

Here's another one I saw in another rerun:

   FAILED  esh-var-test/interp-concat-cmd-external

Running 110 tests (2023-09-13 23:19:42+0200, selector ‘(not (or (tag
:expensive-test) (tag :unstable) (tag :nativecomp)))’)
Loading em-alias...
Loading em-banner...
Loading em-basic...
Loading em-cmpl...
Loading em-extpipe...
Loading em-glob...
Loading em-hist...
Loading em-ls...
Loading em-pred...
Loading em-prompt...
Loading em-script...
Loading em-term...
Loading em-unix...
   passed    1/110  esh-var-test/alias/export (0.178462 sec)
   passed    2/110  esh-var-test/alias/function (0.003780 sec)
   passed    3/110  esh-var-test/alias/function-pair (0.004611 sec)
   passed    4/110  esh-var-test/alias/local-variables (0.006019 sec)
   passed    5/110  esh-var-test/alias/string (0.004543 sec)
   passed    6/110  esh-var-test/alias/string/prefer-lisp (0.002898 sec)
   passed    7/110  esh-var-test/alias/symbol (0.003406 sec)
   passed    8/110  esh-var-test/alias/symbol-pair (0.007461 sec)
   passed    9/110  esh-var-test/columns-var (0.012501 sec)
   passed   10/110  esh-var-test/command-interp (0.007292 sec)
   passed   11/110  esh-var-test/command-interp-splice (0.004153 sec)
   passed   12/110  esh-var-test/export (0.006411 sec)
   passed   13/110  esh-var-test/gid-var (0.002620 sec)
   passed   14/110  esh-var-test/inside-emacs-var (0.004839 sec)
   passed   15/110  esh-var-test/inside-emacs-var-split-indices (0.002154 sec)
   passed   16/110  esh-var-test/interp-cmd (0.004522 sec)
   passed   17/110  esh-var-test/interp-cmd-external (0.112656 sec)
   passed   18/110  esh-var-test/interp-cmd-external-indices (0.113898 sec)
   passed   19/110  esh-var-test/interp-cmd-indices (0.003645 sec)
   passed   20/110  esh-var-test/interp-concat-cmd (0.205057 sec)
Test esh-var-test/interp-concat-cmd-external backtrace:
  signal(ert-test-failed (((should (eshell-match-output regexp)) :form
  ert-fail(((should (eshell-match-output regexp)) :form (eshell-match-
  eshell-match-command-output("echo ${echo hi}-${*echo there}" "hi-the
  #f(compiled-function () #<bytecode 0x498530d8d28fcbf>)()
  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-extern
  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-external condition:
    Command logs: command: "echo ${echo hi}-${*echo there}"

                  ----------------------------------------
                  [process] started external process ‘echo’
                  ----------------------------------------
                  [process] sentinel for external process ‘echo’: "finished
                  "
                  ----------------------------------------
                  [process] finished external process ‘echo’
    (ert-test-failed
     ((should (eshell-match-output regexp)) :form
      (eshell-match-output "hi-there\n") :value nil :explanation
      (mismatched-output (command "echo ${echo hi}-${*echo there}\n")
			 (output "hi-\n") (regexp "hi-there\n"))))
   FAILED   21/110  esh-var-test/interp-concat-cmd-external (0.728591
sec) at lisp/eshell/esh-var-tests.el:292
   passed   22/110  esh-var-test/interp-concat-cmd2 (0.004187 sec)
   passed   23/110  esh-var-test/interp-concat-lisp (0.002859 sec)
   passed   24/110  esh-var-test/interp-concat-lisp2 (0.004121 sec)
   passed   25/110  esh-var-test/interp-convert-cmd-multiline (0.004131 sec)
   passed   26/110  esh-var-test/interp-convert-cmd-number (0.001232 sec)
   passed   27/110  esh-var-test/interp-convert-cmd-split-indices (0.005519 sec)
   passed   28/110  esh-var-test/interp-convert-cmd-string-newline
(0.001249 sec)
   passed   29/110  esh-var-test/interp-convert-quoted-var-number (0.003763 sec)
   passed   30/110
esh-var-test/interp-convert-quoted-var-split-indices (0.002441 sec)
   passed   31/110  esh-var-test/interp-convert-var-number (0.004204 sec)
   passed   32/110  esh-var-test/interp-convert-var-split-indices (0.007541 sec)
   passed   33/110  esh-var-test/interp-lisp (0.003046 sec)
   passed   34/110  esh-var-test/interp-lisp-indices (0.003134 sec)
   passed   35/110  esh-var-test/interp-list-var (0.002291 sec)
   passed   36/110  esh-var-test/interp-list-var-concat (0.001819 sec)
   passed   37/110  esh-var-test/interp-quoted-var (0.003009 sec)
   passed   38/110  esh-var-test/interp-quoted-var-concat (0.003025 sec)
   passed   39/110  esh-var-test/interp-temp-cmd (0.013814 sec)
   passed   40/110  esh-var-test/interp-var (0.001271 sec)
   passed   41/110  esh-var-test/interp-var-assoc (0.004091 sec)
   passed   42/110  esh-var-test/interp-var-indices-subcommand (0.176522 sec)
   passed   43/110  esh-var-test/interp-var-indices/list (0.013073 sec)
   passed   44/110  esh-var-test/interp-var-indices/ring (0.011317 sec)
   passed   45/110  esh-var-test/interp-var-indices/split (0.011973 sec)
   passed   46/110  esh-var-test/interp-var-indices/vector (0.012646 sec)
   passed   47/110  esh-var-test/interp-var-length-alist (0.002014 sec)
   passed   48/110  esh-var-test/interp-var-length-list (0.005285 sec)
   passed   49/110  esh-var-test/interp-var-length-string (0.001555 sec)
   passed   50/110  esh-var-test/interp-var-regexp-split-indices (0.010098 sec)
   passed   51/110  esh-var-test/interp-var-splice (0.001259 sec)
   passed   52/110  esh-var-test/interp-var-splice-concat (0.002406 sec)
   passed   53/110  esh-var-test/interp-var-string-split-indices (0.009873 sec)
   passed   54/110  esh-var-test/last-arg-var (0.005632 sec)
   passed   55/110  esh-var-test/last-arg-var-indices (0.021506 sec)
   passed   56/110  esh-var-test/last-arg-var-split-indices (0.011228 sec)
   passed   57/110  esh-var-test/last-result-var (0.005804 sec)
   passed   58/110  esh-var-test/last-result-var-ext-cmd (0.226047 sec)
   passed   59/110  esh-var-test/last-result-var-split-indices (0.031719 sec)
   passed   60/110  esh-var-test/last-result-var-twice (0.004827 sec)
   passed   61/110  esh-var-test/last-status-var-ext-cmd (0.242608 sec)
   passed   62/110  esh-var-test/last-status-var-lisp-command (0.010839 sec)
   passed   63/110  esh-var-test/last-status-var-lisp-form (0.005407 sec)
   passed   64/110  esh-var-test/last-status-var-lisp-form-2 (0.006529 sec)
   passed   65/110  esh-var-test/lines-var (0.003589 sec)
   passed   66/110  esh-var-test/local-variables (0.023687 sec)
   passed   67/110  esh-var-test/pager-var/default (0.017587 sec)
   passed   68/110  esh-var-test/pager-var/set (0.087502 sec)
   passed   69/110  esh-var-test/pager-var/set-locally (0.012173 sec)
   passed   70/110  esh-var-test/pager-var/unset (0.005189 sec)
   passed   71/110  esh-var-test/path-var/local-directory (0.003602 sec)
Tramp: Sending command ‘exec sh -i’
Tramp: Found remote shell prompt on ‘SK-MacBook-Pro’
   passed   72/110  esh-var-test/path-var/preserve-across-hosts (0.866043 sec)
   passed   73/110  esh-var-test/path-var/remote-directory (0.083372 sec)
   passed   74/110  esh-var-test/path-var/set (0.014802 sec)
   passed   75/110  esh-var-test/path-var/set-locally (0.008608 sec)
   passed   76/110  esh-var-test/quote-interp-var-indices-subcommand
(0.236072 sec)
   passed   77/110  esh-var-test/quoted-interp-cmd (0.004823 sec)
   passed   78/110  esh-var-test/quoted-interp-cmd-indices (0.047686 sec)
   passed   79/110  esh-var-test/quoted-interp-concat-cmd (0.002995 sec)
   passed   80/110  esh-var-test/quoted-interp-convert-cmd-multiline
(0.002892 sec)
   passed   81/110  esh-var-test/quoted-interp-convert-cmd-number (0.002594 sec)
   passed   82/110
esh-var-test/quoted-interp-convert-cmd-split-indices (0.002789 sec)
   passed   83/110
esh-var-test/quoted-interp-convert-cmd-string-newline (0.005021 sec)
   passed   84/110
esh-var-test/quoted-interp-convert-quoted-var-number (0.008607 sec)
   passed   85/110
esh-var-test/quoted-interp-convert-quoted-var-split-indices (0.007789
sec)
   passed   86/110  esh-var-test/quoted-interp-convert-var-number (0.002748 sec)
   passed   87/110
esh-var-test/quoted-interp-convert-var-split-indices (0.007919 sec)
   passed   88/110  esh-var-test/quoted-interp-lisp (0.001791 sec)
   passed   89/110  esh-var-test/quoted-interp-lisp-indices (0.003300 sec)
   passed   90/110  esh-var-test/quoted-interp-list-var (0.001912 sec)
   passed   91/110  esh-var-test/quoted-interp-list-var-concat (0.002009 sec)
   passed   92/110  esh-var-test/quoted-interp-quoted-var (0.003799 sec)
   passed   93/110  esh-var-test/quoted-interp-temp-cmd (0.017058 sec)
   passed   94/110  esh-var-test/quoted-interp-var (0.001892 sec)
   passed   95/110  esh-var-test/quoted-interp-var-assoc (0.021957 sec)
   passed   96/110  esh-var-test/quoted-interp-var-indices (0.017924 sec)
   passed   97/110  esh-var-test/quoted-interp-var-length-alist (0.017236 sec)
   passed   98/110  esh-var-test/quoted-interp-var-length-list (0.006038 sec)
   passed   99/110  esh-var-test/quoted-interp-var-length-string (0.001831 sec)
   passed  100/110
esh-var-test/quoted-interp-var-regexp-split-indices (0.017895 sec)
   passed  101/110  esh-var-test/quoted-interp-var-splice (0.005310 sec)
   passed  102/110  esh-var-test/quoted-interp-var-splice-concat (0.002805 sec)
   passed  103/110  esh-var-test/quoted-interp-var-split-indices (0.005452 sec)
   passed  104/110
esh-var-test/quoted-interp-var-string-split-indices (0.029075 sec)
   passed  105/110  esh-var-test/set/env-var (0.002507 sec)
   passed  106/110  esh-var-test/set/symbol (0.002819 sec)
   passed  107/110  esh-var-test/setq (0.005122 sec)
   passed  108/110  esh-var-test/uid-var (0.021527 sec)
   passed  109/110  esh-var-test/unset/env-var (0.002078 sec)
   passed  110/110  esh-var-test/unset/symbol (0.002711 sec)

Ran 110 tests, 109 results as expected, 1 unexpected (2023-09-13
23:19:46+0200, 4.193564 sec)

1 unexpected results:
   FAILED  esh-var-test/interp-concat-cmd-external

make[3]: *** [lisp/eshell/esh-var-tests.log] Error 1

bug#65602: 30.0.50; eshell-test/{elisp,subcommand}-reset-in-pipeline fails intermittently on macOS

[Jim Porter]

On 9/13/2023 2:33 PM, Stefan Kangas wrote:
> Stefan Kangas <stefankangas@gmail.com> writes:
> 
>> I spoke too soon, as I'm now seeing the below two failures.
>>
>>     FAILED   42/110  esh-var-test/interp-var-indices-subcommand (0.787189 sec) at lisp/eshell/esh-var-tests.el:184
>>
>>     FAILED   5/11  eshell-test/eshell-command/simple (0.670351 sec) at lisp/eshell/eshell-tests.el:41
> 
> Here's another one I saw in another rerun:
> 
>     FAILED  esh-var-test/interp-concat-cmd-external

Hmm. I pushed a commit to add additional instrumentation to this code 
(ef2bd5e4875). Could you try that out and report the results?

You could also try adding something like "(setq eshell-debug-command 
'(form))" to the top of "test/lisp/eshell/eshell-tests-helpers.el", and 
then "rm test/lisp/eshell/*.elc" to force a full recompile of the tests. 
That'll add excessive amounts of logging for Eshell's s-expr 
manipulation, and it might produce something useful. (Warning that it 
can also include things like your env vars in the logs, so be careful 
about uploading it.)

bug#65602: 30.0.50; eshell-test/{elisp,subcommand}-reset-in-pipeline fails intermittently on macOS

[Stefan Kangas]

Jim Porter <jporterbugs@gmail.com> writes:

> Hmm. I pushed a commit to add additional instrumentation to this code
> (ef2bd5e4875). Could you try that out and report the results?

I see more failures now, which might indicate that they are more easily
triggered.  I only did one run so far though.

> You could also try adding something like "(setq eshell-debug-command
> '(form))" to the top of "test/lisp/eshell/eshell-tests-helpers.el", and
> then "rm test/lisp/eshell/*.elc" to force a full recompile of the tests.
> That'll add excessive amounts of logging for Eshell's s-expr
> manipulation, and it might produce something useful.

I have sent the logs to you off-list.

> (Warning that it can also include things like your env vars in the
> logs, so be careful about uploading it.)

Noted, thanks for the heads up.

bug#65602: 30.0.50; eshell-test/{elisp,subcommand}-reset-in-pipeline fails intermittently on macOS

[Jim Porter]

On 9/14/2023 12:14 PM, Stefan Kangas wrote:
> I have sent the logs to you off-list.

Thanks for the logs. They're pretty large, so I'll have to take some 
extra time to look them over, but I'm beginning to wonder if there's a 
bug in process.c. In the logs for em-unix-tests, I see messages for the 
start of the "echo" process and its sentinel, but nothing for the output 
filter, even though we *should* be getting output. I'll keep thinking 
about this, and possibly add some further instrumentation to narrow this 
down...

bug#65602: 30.0.50; eshell-test/{elisp,subcommand}-reset-in-pipeline fails intermittently on macOS

[Jim Porter]

On 9/14/2023 12:33 PM, Jim Porter wrote:
> On 9/14/2023 12:14 PM, Stefan Kangas wrote:
>> I have sent the logs to you off-list.
> 
> Thanks for the logs. They're pretty large, so I'll have to take some 
> extra time to look them over, but I'm beginning to wonder if there's a 
> bug in process.c. In the logs for em-unix-tests, I see messages for the 
> start of the "echo" process and its sentinel, but nothing for the output 
> filter, even though we *should* be getting output. I'll keep thinking 
> about this, and possibly add some further instrumentation to narrow this 
> down...

I pushed some minor changes to the logging (cadd3326625), and a 
mostly-unrelated fix to Eshell's iterative evaluation that I noticed 
from perusing the logs (one day I should really just rip that out and 
replace it with generator.el...).

In particular, I added logging for the actual command-line args that we 
pass to external commands. That should help to narrow down whether we're 
calling the subprocess correctly, or if there's some issue where the 
expected output gets lost on the way somewhere...

bug#65602: 30.0.50; eshell-test/{elisp,subcommand}-reset-in-pipeline fails intermittently on macOS

[Stefan Kangas]

Jim Porter <jporterbugs@gmail.com> writes:

> I pushed some minor changes to the logging (cadd3326625), and a
> mostly-unrelated fix to Eshell's iterative evaluation that I noticed
> from perusing the logs (one day I should really just rip that out and
> replace it with generator.el...).
>
> In particular, I added logging for the actual command-line args that we
> pass to external commands. That should help to narrow down whether we're
> calling the subprocess correctly, or if there's some issue where the
> expected output gets lost on the way somewhere...

After several reruns, I was able to reproduce some additional failures,
but they are getting harder to reproduce.  I just switched to using a
native-comp build, and I'm not sure if that will affect the result.

I've sent you these log files off-list:

* -rw------- 1 sk staff 3.8K 2023-09-15 13:38 esh-var-tests.log.gz
* -rw------- 1 sk staff  877 2023-09-15 13:38 eshell-tests.log.gz

bug#65602: 30.0.50; eshell-test/{elisp,subcommand}-reset-in-pipeline fails intermittently on macOS

[Jim Porter]

On 9/15/2023 5:14 AM, Stefan Kangas wrote:
> After several reruns, I was able to reproduce some additional failures,
> but they are getting harder to reproduce.  I just switched to using a
> native-comp build, and I'm not sure if that will affect the result.

That's good. At least we're making progress.

While testing out some other in-progress patches, I managed to change 
the timings of things locally by enough that I could reliably trigger 
some similar failures. I've pushed my fix to master as 146bd41ddef.

Hopefully these are the same that you're seeing, but I'm not 100% 
certain. (I've also recently pushed a couple of fixes to the debug 
instrumentation - I had broken the "form" instrumentation - but I think 
all the issues we're seeing are related to process timings anyway.)