bug#33839: 26.1.90; Emacs occasionally fails to receive asynchronous subprocess output in batch mode

bug#33839: 26.1.90; Emacs occasionally fails to receive asynchronous subprocess output in batch mode

[Philipp]

Add the following code to /tmp/form.el:

(require 'cl-lib)
(with-temp-buffer
  (let ((proc (make-process :name "test"
                            :command '("bash" "-c" "echo stdout; echo stderr >&2")
                            :buffer (current-buffer)
                            :connection-type 'pipe
                            :sentinel #'ignore
                            :noquery t
                            :coding '(utf-8-unix . utf-8-unix))))
    (when (process-live-p proc)
      (process-send-eof proc))
    (while (process-live-p proc)
      (accept-process-output proc))
    (cl-assert (equal (buffer-string) "stdout\nstderr\n") :show-args)))

Then evaluate this form repeatedly.  Occasionally the buffer is empty
and the assertion triggers.  For example:

$ for i in {1..100}; do emacs -Q -batch -l /tmp/form.el ; done
Assertion failed: (equal (buffer-string) "stdout
stderr
"), ""
Assertion failed: (equal (buffer-string) "stdout
stderr
"), ""

i.e. here the output didn't arrive in 2 of 100 iterations.


In GNU Emacs 26.1.90 (build 5, x86_64-apple-darwin18.0.0, NS appkit-1671.10 Version 10.14.1 (Build 18B75))
 of 2018-12-22
Repository revision: 24ddea074a2e61f7accde60cdf941ba67b1ce82a
Windowing system distributor 'Apple', version 10.3.1671
Recent messages:
For information about GNU Emacs and the GNU system, type C-h C-a.

Configured using:
 'configure --enable-checking --enable-check-lisp-object-type
 --enable-gtk-deprecation-warnings --with-modules --without-xml2
 --without-pop --with-mailutils --enable-gcc-warnings=warn-only
 MAKEINFO=/usr/local/opt/texinfo/bin/makeinfo 'CFLAGS=-O0 -ggdb3'
 LDFLAGS=-O0'

Configured features:
JPEG NOTIFY ACL GNUTLS ZLIB TOOLKIT_SCROLL_BARS NS MODULES THREADS LCMS2

Important settings:
  value of $LANG: de_DE.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
  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
  auto-composition-mode: t
  auto-encryption-mode: t
  auto-compression-mode: t
  line-number-mode: t
  transient-mark-mode: t

Load-path shadows:
None found.

Features:
(shadow sort mail-extr emacsbug message rmc puny seq dired
dired-loaddefs format-spec rfc822 mml easymenu mml-sec epa derived epg
epg-config gnus-util rmail rmail-loaddefs mm-decode mm-bodies mm-encode
mail-parse rfc2231 mailabbrev gmm-utils mailheader sendmail rfc2047
rfc2045 ietf-drums mm-util mail-prsvr mail-utils phst pcase ffap
thingatpt url-parse auth-source cl-seq eieio byte-opt bytecomp
byte-compile cconv eieio-core cl-macs gv eieio-loaddefs password-cache
url-vars subr-x rx gnutls dbus xml cl-loaddefs cl-lib elec-pair
time-date tooltip eldoc electric uniquify ediff-hook vc-hooks
lisp-float-type 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 elisp-mode lisp-mode
prog-mode register page menu-bar rfn-eshadow isearch timer select
scroll-bar mouse jit-lock font-lock syntax facemenu font-core
term/tty-colors frame cl-generic 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 charscript charprop case-table epa-hook jka-cmpr-hook
help simple abbrev obarray minibuffer cl-preloaded nadvice loaddefs
button faces cus-face macroexp files text-properties overlay sha1 md5
base64 format env code-pages mule custom widget hashtable-print-readable
backquote threads kqueue cocoa ns lcms2 multi-tty make-network-process
emacs)

Memory information:
((conses 16 216710 8580)
 (symbols 48 21650 0)
 (miscs 40 59 186)
 (strings 32 32914 1496)
 (string-bytes 1 892039)
 (vectors 16 37089)
 (vector-slots 8 751562 17790)
 (floats 8 56 60)
 (intervals 56 210 0)
 (buffers 992 11))

bug#33839: 26.1.90; Emacs occasionally fails to receive asynchronous subprocess output in batch mode

[Eli Zaretskii]

> From: Philipp <p.stephani2@gmail.com>
> Date: Sun, 23 Dec 2018 03:28:53 +0100
> 
> (with-temp-buffer
>   (let ((proc (make-process :name "test"
>                             :command '("bash" "-c" "echo stdout; echo stderr >&2")
>                             :buffer (current-buffer)
>                             :connection-type 'pipe
>                             :sentinel #'ignore
>                             :noquery t
>                             :coding '(utf-8-unix . utf-8-unix))))
>     (when (process-live-p proc)
>       (process-send-eof proc))
>     (while (process-live-p proc)
>       (accept-process-output proc))
>     (cl-assert (equal (buffer-string) "stdout\nstderr\n") :show-args)))
> 
> Then evaluate this form repeatedly.  Occasionally the buffer is empty
> and the assertion triggers.

Isn't there an inherent race condition here?

bug#33839: 26.1.90; Emacs occasionally fails to receive asynchronous subprocess output in batch mode

[Philipp Stephani]

Am So., 23. Dez. 2018 um 16:22 Uhr schrieb Eli Zaretskii <eliz@gnu.org>:
>
> > From: Philipp <p.stephani2@gmail.com>
> > Date: Sun, 23 Dec 2018 03:28:53 +0100
> >
> > (with-temp-buffer
> >   (let ((proc (make-process :name "test"
> >                             :command '("bash" "-c" "echo stdout; echo stderr >&2")
> >                             :buffer (current-buffer)
> >                             :connection-type 'pipe
> >                             :sentinel #'ignore
> >                             :noquery t
> >                             :coding '(utf-8-unix . utf-8-unix))))
> >     (when (process-live-p proc)
> >       (process-send-eof proc))
> >     (while (process-live-p proc)
> >       (accept-process-output proc))
> >     (cl-assert (equal (buffer-string) "stdout\nstderr\n") :show-args)))
> >
> > Then evaluate this form repeatedly.  Occasionally the buffer is empty
> > and the assertion triggers.
>
> Isn't there an inherent race condition here?

Maybe? If so, then it should be documented, with an explanation how to
write this in a race-free manner. (It seems waiting for the process
sentinel to run works reliably.)

bug#33839: 26.1.90; Emacs occasionally fails to receive asynchronous subprocess output in batch mode

[Eli Zaretskii]

> From: Philipp Stephani <p.stephani2@gmail.com>
> Date: Sun, 23 Dec 2018 17:45:31 +0100
> Cc: 33839@debbugs.gnu.org
> 
> Am So., 23. Dez. 2018 um 16:22 Uhr schrieb Eli Zaretskii <eliz@gnu.org>:
> >
> > > From: Philipp <p.stephani2@gmail.com>
> > > Date: Sun, 23 Dec 2018 03:28:53 +0100
> > >
> > > (with-temp-buffer
> > >   (let ((proc (make-process :name "test"
> > >                             :command '("bash" "-c" "echo stdout; echo stderr >&2")
> > >                             :buffer (current-buffer)
> > >                             :connection-type 'pipe
> > >                             :sentinel #'ignore
> > >                             :noquery t
> > >                             :coding '(utf-8-unix . utf-8-unix))))
> > >     (when (process-live-p proc)
> > >       (process-send-eof proc))
> > >     (while (process-live-p proc)
> > >       (accept-process-output proc))
> > >     (cl-assert (equal (buffer-string) "stdout\nstderr\n") :show-args)))
> > >
> > > Then evaluate this form repeatedly.  Occasionally the buffer is empty
> > > and the assertion triggers.
> >
> > Isn't there an inherent race condition here?
> 
> Maybe? If so, then it should be documented, with an explanation how to
> write this in a race-free manner.

Can you tell why you used the process-live-p condition for calling
accept-process-output?  What happens if you do that unconditionally?

bug#33839: 26.1.90; Emacs occasionally fails to receive asynchronous subprocess output in batch mode

[Philipp Stephani]

Am So., 23. Dez. 2018 um 17:45 Uhr schrieb Philipp Stephani
<p.stephani2@gmail.com>:
>
> Am So., 23. Dez. 2018 um 16:22 Uhr schrieb Eli Zaretskii <eliz@gnu.org>:
> >
> > > From: Philipp <p.stephani2@gmail.com>
> > > Date: Sun, 23 Dec 2018 03:28:53 +0100
> > >
> > > (with-temp-buffer
> > >   (let ((proc (make-process :name "test"
> > >                             :command '("bash" "-c" "echo stdout; echo stderr >&2")
> > >                             :buffer (current-buffer)
> > >                             :connection-type 'pipe
> > >                             :sentinel #'ignore
> > >                             :noquery t
> > >                             :coding '(utf-8-unix . utf-8-unix))))
> > >     (when (process-live-p proc)
> > >       (process-send-eof proc))
> > >     (while (process-live-p proc)
> > >       (accept-process-output proc))
> > >     (cl-assert (equal (buffer-string) "stdout\nstderr\n") :show-args)))
> > >
> > > Then evaluate this form repeatedly.  Occasionally the buffer is empty
> > > and the assertion triggers.
> >
> > Isn't there an inherent race condition here?
>
> Maybe? If so, then it should be documented, with an explanation how to
> write this in a race-free manner. (It seems waiting for the process
> sentinel to run works reliably.)

This is also probably closely related to
https://debbugs.gnu.org/cgi/bugreport.cgi?bug=31214.

bug#33839: 26.1.90; Emacs occasionally fails to receive asynchronous subprocess output in batch mode

[Philipp Stephani]

Am So., 23. Dez. 2018 um 17:54 Uhr schrieb Eli Zaretskii <eliz@gnu.org>:
>
> > From: Philipp Stephani <p.stephani2@gmail.com>
> > Date: Sun, 23 Dec 2018 17:45:31 +0100
> > Cc: 33839@debbugs.gnu.org
> >
> > Am So., 23. Dez. 2018 um 16:22 Uhr schrieb Eli Zaretskii <eliz@gnu.org>:
> > >
> > > > From: Philipp <p.stephani2@gmail.com>
> > > > Date: Sun, 23 Dec 2018 03:28:53 +0100
> > > >
> > > > (with-temp-buffer
> > > >   (let ((proc (make-process :name "test"
> > > >                             :command '("bash" "-c" "echo stdout; echo stderr >&2")
> > > >                             :buffer (current-buffer)
> > > >                             :connection-type 'pipe
> > > >                             :sentinel #'ignore
> > > >                             :noquery t
> > > >                             :coding '(utf-8-unix . utf-8-unix))))
> > > >     (when (process-live-p proc)
> > > >       (process-send-eof proc))
> > > >     (while (process-live-p proc)
> > > >       (accept-process-output proc))
> > > >     (cl-assert (equal (buffer-string) "stdout\nstderr\n") :show-args)))
> > > >
> > > > Then evaluate this form repeatedly.  Occasionally the buffer is empty
> > > > and the assertion triggers.
> > >
> > > Isn't there an inherent race condition here?
> >
> > Maybe? If so, then it should be documented, with an explanation how to
> > write this in a race-free manner.
>
> Can you tell why you used the process-live-p condition for calling
> accept-process-output?

Because it seemed logical to do so: while the process is running, wait
for process output. I don't think the manual states that output can
arrive after the process has finished, but if that's the case, then it
should do so.

> What happens if you do that unconditionally?

You mean, without a while loop? It works in this specific case, but
doesn't work in other cases, e.g. when a timer runs while the process
is still running.
To make this work reliably, a loop is required because there's no
guarantee that accept-process-output returns only when the process has
finished.

bug#33839: 26.1.90; Emacs occasionally fails to receive asynchronous subprocess output in batch mode

[Eli Zaretskii]

> From: Philipp Stephani <p.stephani2@gmail.com>
> Date: Tue, 25 Dec 2018 17:41:17 +0100
> Cc: 33839@debbugs.gnu.org
> 
> > What happens if you do that unconditionally?
> 
> You mean, without a while loop? It works in this specific case, but
> doesn't work in other cases, e.g. when a timer runs while the process
> is still running.
> To make this work reliably, a loop is required because there's no
> guarantee that accept-process-output returns only when the process has
> finished.

What I meant was that this condition "refuses" to take output from the
subprocess if it has exited.  I'm questioning the correctness of this,
since it could well be that the last portion of that output is still
buffered somewhere, even though we already got SIGCHLD.

I'm not sure I understand the example with a timer, but if in that
situation your program is willing to accept output even after the
subprocess already exited, does it work correctly then?

bug#33839: 26.1.90; Emacs occasionally fails to receive asynchronous subprocess output in batch mode

[Paul Eggert]

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

[This is a corrected version of email I mistakenly sent elsewhere.]

 > I don't think the manual states that output can
 > arrive after the process has finished, but if that's the case, then it
 > should do so.

Good point, and I installed the attached patch into emacs-26 to try to do that.

As this bug report seems to stem from a misunderstanding of 
accept-process-output (quite understandable, as its functionality is obscure) 
I'm taking the liberty of closing the report. If I'm wrong please feel free to 
reopen it.

[-- Attachment #2: 0001-Improve-accept-process-process-doc.patch --]
[-- Type: text/x-patch, Size: 3028 bytes --]

From c9fdd1b4965ebd02aa408f878320c4955f5e2cc7 Mon Sep 17 00:00:00 2001
From: Paul Eggert <eggert@cs.ucla.edu>
Date: Thu, 27 Dec 2018 12:52:45 -0800
Subject: [PATCH] Improve accept-process-process doc

* doc/lispref/processes.texi (Accepting Output):
* src/process.c (Faccept_process_output):
Document that (accept-process-output P) can return non-nil
even after P has exited, and that it can return nil even if P
is still running (Bug#33839).
---
 doc/lispref/processes.texi | 7 +++++--
 src/process.c              | 7 ++++---
 2 files changed, 9 insertions(+), 5 deletions(-)

diff --git a/doc/lispref/processes.texi b/doc/lispref/processes.texi
index 623be09cc6..2aca7f82a1 100644
--- a/doc/lispref/processes.texi
+++ b/doc/lispref/processes.texi
@@ -1795,7 +1795,8 @@ Accepting Output
 This function allows Emacs to read pending output from processes.  The
 output is given to their filter functions.  If @var{process} is
 non-@code{nil} then this function does not return until some output
-has been received from @var{process}.
+has been received from @var{process} or @var{process} has closed the
+connection.
 
 The arguments @var{seconds} and @var{millisec} let you specify timeout
 periods.  The former specifies a period measured in seconds and the
@@ -1820,7 +1821,9 @@ Accepting Output
 
 The function @code{accept-process-output} returns non-@code{nil} if it
 got output from @var{process}, or from any process if @var{process} is
-@code{nil}.  It returns @code{nil} if the timeout expired before output
+@code{nil}; this can occur even after a process has exited if the
+corresponding connection contains buffered data.  The function returns
+@code{nil} if the timeout expired or the connection was closed before output
 arrived.
 @end defun
 
diff --git a/src/process.c b/src/process.c
index e306b2ae9e..4dafee8cbe 100644
--- a/src/process.c
+++ b/src/process.c
@@ -4581,8 +4581,8 @@ DEFUN ("accept-process-output", Faccept_process_output, Saccept_process_output,
        0, 4, 0,
        doc: /* Allow any pending output from subprocesses to be read by Emacs.
 It is given to their filter functions.
-Optional argument PROCESS means do not return until output has been
-received from PROCESS.
+Optional argument PROCESS means to return only after output is
+received from PROCESS or PROCESS closes the connection.
 
 Optional second argument SECONDS and third argument MILLISEC
 specify a timeout; return after that much time even if there is
@@ -4594,7 +4594,8 @@ If optional fourth argument JUST-THIS-ONE is non-nil, accept output
 from PROCESS only, suspending reading output from other processes.
 If JUST-THIS-ONE is an integer, don't run any timers either.
 Return non-nil if we received any output from PROCESS (or, if PROCESS
-is nil, from any process) before the timeout expired.  */)
+is nil, from any process) before the timeout expired or the
+corresponding connection was closed.  */)
   (Lisp_Object process, Lisp_Object seconds, Lisp_Object millisec,
    Lisp_Object just_this_one)
 {
-- 
2.17.1