bug#50166: 28.0.50; ECM for possible process-status/sentinel bug

bug#50166: 28.0.50; ECM for possible process-status/sentinel bug

[Adam Porter]

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

[As originally posted at
https://lists.gnu.org/archive/html/emacs-devel/2021-08/msg00654.html]

Hi,

The attached file provides an ECM for a possible bug in Emacs's process
handling.  The rub is whether a process sentinel may be called with a
STATUS string of "finished\n" while the process's `process-status' is
`open': If that is expected, then this may not indicate a bug (but
perhaps an issue that needs to be more prominently documented).  But if
it's not supposed to happen, then this may provide a means to reproduce
the behavior and troubleshoot the bug.

This ECM works by making 10 (by default) curl `pipe' processes that send
requests to httpbin.org.  When each process is finished, the process
sentinel should conclude by killing the process's buffer.

This appears to work most of the time, especially with low numbers of
processes (like 1-3).  But as the number of processes is increased,
sometimes one or more of the attempts to kill a process's buffer result
in the user's being prompted to kill the buffer due to the process still
running (an obvious problem when happening in library code that the user
should not be concerned with).  As the number of processes increases,
the number of process buffers that prompt seems to increase (e.g. with
15 processes, 1-2 prompts seems common).

A possible workaround would be to check the process's status before
attempting to kill the buffer, however that would seem to raise a
problem: according to the Elisp manual, calls to the sentinel may be
coalesced when a process's status changes quickly, so if the sentinel
simply did not kill the buffer if the process were still alive, it's
unclear whether the sentinel will be called a final time, after the
process's status is `closed'; if not, the buffer would never be killed.
Alternatively, the sentinel could loop while checking `process-status',
but that would obviously be undesirable, and would seem like working
around a bug (and it might be the wrong thing to do in general,
depending on the process's and sentinel's purposes).

To test this ECM:

1.  Evaluate this file (with lexical-binding).

2.  Eval (argh).

3.  The messages buffer should show the first line of the HTTP response
body for requests 1-10, as well as a "killing buffer..."  line for each
curl process's buffer.  There should be NO "Buffer has a running
process; kill it?" prompts.

4.  But, usually, there will be one or two of those prompts.  When there
are, you can see that the buffer's process has a (process-status) value
of "open" rather than "closed", even though the process's sentinel was
called with "finished\n" as the status argument.

So far, this has been reproduced on Emacs 26.3, 27.2 (with Eric
Abrahamsen's help), and 28.0.50 (built on 2021-07-05), on GNU/Linux.

Alternatively, if this simply demonstrates a lack of understanding on my
part of how to properly use sentinels, I'd be grateful to be corrected.

[This file has also been posted at
https://gist.github.com/alphapapa/daa36dc3388dec694602e06fe6d114b7, and
may be updated there if necessary.]

Thanks,
Adam

[-- Attachment #2: emacs-process-sentinel-ecm.el --]
[-- Type: text/x-emacs-lisp, Size: 5363 bytes --]

;;; emacs-process-sentinel-ecm.el ---                               -*- lexical-binding: t; -*-

;; This file provides an ECM for a possible bug in Emacs's process
;; handling.  The rub is whether a process sentinel may be called with
;; a STATUS string of "finished\n" while the process's
;; `process-status' is `open': If that is expected, then this may not
;; indicate a bug (but perhaps an issue that needs to be more
;; prominently documented).  But if it's not supposed to happen, then
;; this may provide a means to reproduce the behavior and troubleshoot
;; the bug.

;; This ECM works by making 10 (by default) curl `pipe' processes that
;; send requests to httpbin.org.  When each process is finished, the
;; process sentinel should conclude by killing the process's buffer.

;; This appears to work most of the time, especially with low numbers
;; of processes (like 1-3).  But as the number of processes is
;; increased, sometimes one or more of the attempts to kill a
;; process's buffer result in the user's being prompted to kill the
;; buffer due to the process still running (an obvious problem when
;; happening in library code that the user should not be concerned
;; with).  As the number of processes increases, the number of process
;; buffers that prompt seems to increase (e.g. with 15 processes, 1-2
;; prompts seems common).

;; A possible workaround would be to check the process's status before
;; attempting to kill the buffer, however that would seem to raise a
;; problem: according to the Elisp manual, calls to the sentinel may
;; be coalesced when a process's status changes quickly, so if the
;; sentinel simply did not kill the buffer if the process were still
;; alive, it's unclear whether the sentinel will be called a final
;; time, after the process's status is `closed'; if not, the buffer
;; would never be killed.  Alternatively, the sentinel could loop
;; while checking `process-status', but that would obviously be
;; undesirable, and would seem like working around a bug (and it might
;; be the wrong thing to do in general, depending on the process's and
;; sentinel's purposes).

;; To test this ECM:

;; 1.  Evaluate this file (with lexical-binding).

;; 2.  Eval (argh).

;; 3.  The messages buffer should show the first line of the HTTP
;; response body for requests 1-10, as well as a "killing buffer..."
;; line for each curl process's buffer.  There should be NO "Buffer
;; has a running process; kill it?" prompts.

;; 4.  But, usually, there will be one or two of those prompts.  When
;; there are, you can see that the buffer's process has a
;; (process-status) value of "open" rather than "closed", even though
;; the process's sentinel was called with "finished\n" as the status
;; argument.

;; So far, this has been reproduced on Emacs 26.3, 27.2, and 28.0.50
;; (built on 2021-07-05), on GNU/Linux.

(require 'cl-lib)
(require 'rx)

(defvar-local argh-callback nil)

(defun argh ()
  (let* ((i 0))
    (while (< i 10)
      (setq i (1+ i))
      (let ((prefix (format "%s" i)))
        (message "%S"
                 (argh-curl i (lambda (data)
                                (message "%s: %S" prefix data))))))))

(defun argh-curl (num callback)
  (let* ((process-buffer (generate-new-buffer (format "argh-curl-%02d" num)))
         (process (make-process :name "argh-curl"
                                :buffer process-buffer
                                :coding 'binary
                                :command '("curl"
                                           "--silent"
                                           "--compressed"
                                           "--location"
                                           "--dump-header" "-"
                                           "--config" "-")
                                :connection-type 'pipe
                                :sentinel #'argh--sentinel
                                :stderr process-buffer))
         (curl-config "--url https://httpbin.org/get\n"))
    (with-current-buffer process-buffer
      (setf argh-callback callback))
    (process-send-string process curl-config)
    (process-send-eof process)
    process))

(defun argh--sentinel (process-or-buffer status)
  (let ((buffer (cl-typecase process-or-buffer
                  (buffer process-or-buffer)
                  (process (process-buffer process-or-buffer)))))
    (unwind-protect
        (with-current-buffer buffer
          (pcase-exhaustive status
            ("finished\n"
             ;; Curl exited normally.
             (goto-char (point-min))
             (re-search-forward "^\r\n" nil)
             (forward-line 1)
             (funcall argh-callback (buffer-substring (point-at-bol) (point-at-eol))))

            ((or (and (pred numberp) code)
                 (rx "exited abnormally with code " (let code (group (1+ digit)))))
             ;; Curl error.
             nil)

            ("killed\n"
             ;; Curl process killed.
             nil)))
      (pcase status
        ((or "finished\n"
             "killed\n"
             (pred numberp)
             (rx "exited abnormally with code " (1+ digit)))
         (message "killing buffer %S of process.  PROCESS-STATUS:%S  SENTINEL-STATUS-ARG:%S"
                  buffer (process-status (get-buffer-process buffer)) status)
         (kill-buffer buffer))))))

bug#50166: 28.0.50; ECM for possible process-status/sentinel bug

[Lars Ingebrigtsen]

Adam Porter <adam@alphapapa.net> writes:

> The attached file provides an ECM for a possible bug in Emacs's process
> handling.

What does "ECM" stand for?

-- 
(domestic pets only, the antidote for overdose, milk.)
   bloggy blog: http://lars.ingebrigtsen.no

bug#50166: 28.0.50; ECM for possible process-status/sentinel bug

[Adam Porter]

On Sun, Aug 22, 2021 at 4:21 PM Lars Ingebrigtsen <larsi@gnus.org> wrote:
>
> Adam Porter <adam@alphapapa.net> writes:
>
> > The attached file provides an ECM for a possible bug in Emacs's process
> > handling.
>
> What does "ECM" stand for?

According to https://orgmode.org/worg/org-faq.html#ecm:

    This is a French acronym used by some mailing list members; it stands
    for "Exemple Complet Minimal", or "Complete Minimal   Example". The
    term refers to test files that can reliably reproduce a bug with the
    minimal amount of code. When you report a bug to the mailing list, you
    should provide a minimal .org file (with no more text than necessary)
    that demonstrates the bug. See this post for more information.

I learned the term from working on Org, and since Org is part of
Emacs, I assumed it was generally familiar to Emacs maintainers as
well.  My mistake.  :)

bug#50166: 28.0.50; ECM for possible process-status/sentinel bug

[Lars Ingebrigtsen]

Adam Porter <adam@alphapapa.net> writes:

> According to https://orgmode.org/worg/org-faq.html#ecm:
>
>     This is a French acronym used by some mailing list members; it stands
>     for "Exemple Complet Minimal", or "Complete Minimal   Example".

I see.  :-)

The example wasn't that minimal, though, so I shortened it a bit to
understand it better:

;;;  -*- lexical-binding: t; -*-

(defun start-curls ()
  (interactive)
  (dotimes (i 10)
    (let* ((process-buffer (generate-new-buffer (format "argh-curl-%02d" i)))
           (process (make-process :name "argh-"
                                  :buffer process-buffer
                                  :coding 'binary
                                  :command '("curl"
                                             "--silent"
                                             "--compressed"
                                             "--location"
                                             "--dump-header" "-"
                                             "--config" "-")
                                  :connection-type 'pipe
                                  :sentinel #'argh--sentinel
                                  :stderr process-buffer)))
      (process-send-string process "--url https://httpbin.org/get\n")
      (process-send-eof process)
      process)))

(defun argh--sentinel (process status)
  (with-current-buffer (process-buffer process)
    (when (equal (string-clean-whitespace status) "finished")
      (message "status: %s %s %S" (string-clean-whitespace status)
	       (process-status process) process)
      (kill-buffer (current-buffer)))))


And, indeed, after `M-x start-curls' I'm usually prompted for a

Buffer "argh-curl-09<2>" has a running process; kill it? (yes or no)

However, the status messaged by all those say:

status: finished exit #<process argh-<1>>

So somehow process-status can claim that the status is `exit', but
`kill-buffer' then says that the process is alive...  Most puzzling.

-- 
(domestic pets only, the antidote for overdose, milk.)
   bloggy blog: http://lars.ingebrigtsen.no

bug#50166: 28.0.50; ECM for possible process-status/sentinel bug

[Lars Ingebrigtsen]

Lars Ingebrigtsen <larsi@gnus.org> writes:

> However, the status messaged by all those say:
>
> status: finished exit #<process argh-<1>>

Aha!

  (with-current-buffer (process-buffer process)
    (get-buffer-process (current-buffer)))

isn't the same as process!

It's

argh- stderr<7>

vs

#<process argh-<7>>

So when you did a :stderr that pointed to process-buffer, you associated
a second process with the buffer, and that process hadn't died yet.

Without that :stderr in make-process, I see no peculiarities here.

-- 
(domestic pets only, the antidote for overdose, milk.)
   bloggy blog: http://lars.ingebrigtsen.no

bug#50166: 28.0.50; ECM for possible process-status/sentinel bug

[Lars Ingebrigtsen]

Lars Ingebrigtsen <larsi@gnus.org> writes:

> Without that :stderr in make-process, I see no peculiarities here.

So I suspect that this is working as intended?  But the :stderr entry in
the doc string should mention this...

-- 
(domestic pets only, the antidote for overdose, milk.)
   bloggy blog: http://lars.ingebrigtsen.no

bug#50166: 28.0.50; ECM for possible process-status/sentinel bug

[Adam Porter]

On Sun, Aug 22, 2021 at 5:40 PM Lars Ingebrigtsen <larsi@gnus.org> wrote:
>
> Lars Ingebrigtsen <larsi@gnus.org> writes:
>
> > Without that :stderr in make-process, I see no peculiarities here.
>
> So I suspect that this is working as intended?  But the :stderr entry in
> the doc string should mention this...

Thanks for investigating that, Lars.

I guess it would be a good thing if this turned out to be just a
documentation issue.  But if it is, I'm left to wonder what the right
way is to capture the STDERR of a (make-process) process while also
waiting on all of the process's associated processes to exit, have
their output collected into the designated buffers, and their
sentinels run.  The manual says to use (while (accept-process-output
PROCESS)), but apparently that may return while a process's :stderr
process is still running, or something like that...  (The fact that
"process" seems to have some extra meanings in the context--it refers
not only to the program called with `make-process'--seems to add to
the difficulty of reasoning and communicating about these issues.)

As an aside, I tried removing the :stderr argument to make-process in
my plz.el library, but unfortunately it did not help the problem I'm
observing there: that running ERT tests in series, with curl processes
started in quick succession (though only one at a time) leads to
failing tests, apparently related to sentinels not being called after
a process's output has been collected (and running the tests
individually almost always succeeds).  So I don't know if the problem
described in this report is related to that, or whether it's a bug in
my code, my understanding, or a different process-related issue in
Emacs.  It "feels like" they could be loosely related, but what do I
know.  :)

bug#50166: 28.0.50; ECM for possible process-status/sentinel bug

[Lars Ingebrigtsen]

Adam Porter <adam@alphapapa.net> writes:

> I guess it would be a good thing if this turned out to be just a
> documentation issue.

The manual has more here than the doc string:

          If STDERR is a buffer, Emacs will create a pipe process, the
          “standard error process”.  This process will have the default
          filter (*note Filter Functions::), sentinel (*note
          Sentinels::), and coding systems (*note Default Coding
          Systems::).  On the other hand, it will use QUERY-FLAG as its
          query-on-exit flag (*note Query Before Exit::).  It will be
          associated with the STDERR buffer (*note Process Buffers::)
          and send its output (which is the standard error of the main
          process) there.  To get the process object for the standard
          error process, pass the STDERR buffer to ‘get-buffer-process’.

I'll put some of this in the doc string, too.

> But if it is, I'm left to wonder what the right
> way is to capture the STDERR of a (make-process) process while also
> waiting on all of the process's associated processes to exit, have
> their output collected into the designated buffers, and their
> sentinels run.

Create a separate buffer for stderr, pick out the process with
get-buffer-process, and set a sentinel for that process, too.

-- 
(domestic pets only, the antidote for overdose, milk.)
   bloggy blog: http://lars.ingebrigtsen.no

bug#50166: 28.0.50; ECM for possible process-status/sentinel bug

[Lars Ingebrigtsen]

Lars Ingebrigtsen <larsi@gnus.org> writes:

> Create a separate buffer for stderr, pick out the process with
> get-buffer-process, and set a sentinel for that process, too.

Well, that'd be both racey and awkward -- I think the way to really do
this is to create a `make-pipe-process' with its own :sentinel and pass
that in as :stderr in `make-process'.

-- 
(domestic pets only, the antidote for overdose, milk.)
   bloggy blog: http://lars.ingebrigtsen.no

bug#50166: 28.0.50; ECM for possible process-status/sentinel bug

[Lars Ingebrigtsen]

Adam Porter <adam@alphapapa.net> writes:

> (The fact that
> "process" seems to have some extra meanings in the context--it refers
> not only to the program called with `make-process'--seems to add to
> the difficulty of reasoning and communicating about these issues.)

"Process" in Emacs just refers to a "process object" -- it's not tied to
the Unix concept of a process, really.  (But Unix processes are
interacted with via Emacs process objects normally.  :-))

An Emacs process object is something that perhaps gives you bytes and
might accept bytes, so it's a network connection, a UDP server, a
socket, a pipe, a tty, a serial connection or a Unix process.  (And
probably other things I'm forgetting.)

> As an aside, I tried removing the :stderr argument to make-process in
> my plz.el library, but unfortunately it did not help the problem I'm
> observing there: that running ERT tests in series, with curl processes
> started in quick succession (though only one at a time) leads to
> failing tests, apparently related to sentinels not being called after
> a process's output has been collected (and running the tests
> individually almost always succeeds).

If you could come up with a minimal test case for that, that'd be nice.

-- 
(domestic pets only, the antidote for overdose, milk.)
   bloggy blog: http://lars.ingebrigtsen.no

bug#50166: 28.0.50; ECM for possible process-status/sentinel bug

[Lars Ingebrigtsen]

Lars Ingebrigtsen <larsi@gnus.org> writes:

>> As an aside, I tried removing the :stderr argument to make-process in
>> my plz.el library, but unfortunately it did not help the problem I'm
>> observing there: that running ERT tests in series, with curl processes
>> started in quick succession (though only one at a time) leads to
>> failing tests, apparently related to sentinels not being called after
>> a process's output has been collected (and running the tests
>> individually almost always succeeds).
>
> If you could come up with a minimal test case for that, that'd be nice.

Did you make any further progress here?

-- 
(domestic pets only, the antidote for overdose, milk.)
   bloggy blog: http://lars.ingebrigtsen.no

bug#50166: 28.0.50; ECM for possible process-status/sentinel bug

[Adam Porter]

On Wed, Sep 22, 2021 at 3:41 PM Lars Ingebrigtsen <larsi@gnus.org> wrote:
>
> Lars Ingebrigtsen <larsi@gnus.org> writes:
>
> >> As an aside, I tried removing the :stderr argument to make-process in
> >> my plz.el library, but unfortunately it did not help the problem I'm
> >> observing there: that running ERT tests in series, with curl processes
> >> started in quick succession (though only one at a time) leads to
> >> failing tests, apparently related to sentinels not being called after
> >> a process's output has been collected (and running the tests
> >> individually almost always succeeds).
> >
> > If you could come up with a minimal test case for that, that'd be nice.
>
> Did you make any further progress here?

Not yet.  I've been busy with other projects, needed to work on some I
could actually make progress on.  ;)  I intend to look at this again,
but I don't know how soon.  If you have any general advice for this
kind of process-object-related debugging, I'd be grateful.  I've spent
too much time on this doing things that don't make any difference and
don't seem to narrow down the problem space.

For example, am I misusing sentinels here?  In elfeed-curl, Chris
Wellons uses (run-at-time 0 ...) to do most of the response-processing
outside of the sentinel.  I don't know if that's elegant and/or a
hack, and I don't know if it even matters, but trying to fix this
problem in plz.el has felt like throwing wet noodles at a wall and
hoping something sticks.

bug#50166: 28.0.50; ECM for possible process-status/sentinel bug

[Lars Ingebrigtsen]

Adam Porter <adam@alphapapa.net> writes:

> For example, am I misusing sentinels here?

As far as I can tell by skimming the code, you seem to be using
sentinels properly here.  There may well be bugs in the sentinel
triggering code -- there's been various bugs in this area over the
years.

But I don't really have any advice as to debug it more efficiently --
the code in process.c is pretty gnarly and difficult to reason about.

-- 
(domestic pets only, the antidote for overdose, milk.)
   bloggy blog: http://lars.ingebrigtsen.no