unofficial mirror of emacs-devel@gnu.org 
 help / color / mirror / code / Atom feed
* wait_reading_process_ouput hangs in certain cases (w/ patches)
@ 2017-10-24 18:52 Matthias Dahl
  2017-10-25 14:53 ` Eli Zaretskii
  0 siblings, 1 reply; 151+ messages in thread
From: Matthias Dahl @ 2017-10-24 18:52 UTC (permalink / raw)
  To: emacs-devel

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

Hello all,

recursively calling accept-process-output with the first call waiting
for the output of a specific process, can hang Emacs (as-in: it is
waiting forever but can be canceled of course) even though it should
not be the case since data was read.

This is actually not all that uncommon. One example of this is a hang
seen with Magit opening its COMMIT_MSG buffer, reported here [1]. I've
myself run into this problem continuously which is why I started to
debug it in the first place.

The hang with Magit happens in flyspell.el which waits for output from
its spellchecker process through accept-process-output and specifies
that specific process as wait_proc. Now depending on timing (race),
wait_reading_process_output can call the pending timers... which in
turn can call accept-process-output again. This almost always leads
to the spellchecker output being read back in full, so there is no
more data left to be read. Thus the original accept-process-output,
which called wait_reading_process_output, will wait for the data to
become available forever since it has no way to know that those have
already been read.

Naturally one could argue that a timeout should be specified when
calling accept-process-output. But nevertheless I still think this is
a breach of contract. The caller expects accept-process-output to
return as promised when data has been read from the specified process
and it clearly isn't always the case and can hang forever, depending
on timing and the specifics of the data being read.

The attached patches fix this by introducing process output read
accounting -- simply counting the bytes read per process. And using
that data to strategically check in wait_reading_process_output for
data being read while we handed over control to timers and/or filters.

I haven't seen any ill side-effects in my tests and it clearly fixes
the problem seen in [1] as well as I would wager quite a few others
that were probably seen by user's of all kinds of setups that seemed
unpredictable and mysterious and never debugged.

As a side-note: I decided against an artificial metric and went with
simply counting the bytes read, since this does come in handy when
doing debugging and being able to see how much data was read from a
process during specific time intervals.

Also, this still leaves the possibility that wait_reading_process_output
could wait forever while being called without wait_proc and a timeout
set. This could be mitigated as well by some sort of a tick counter that
only increases when no wait_proc was specified and data from processes
were processed. I decided against implementing that for now since imho
the chances of that happening are marginal, if at all present. OTOH,
the semantics in that case are not all that clear and would further add
complexity to an already rather unhealthy function. I am naturally open
to other opinions and implementing this as well if requested. :-)

Any suggestions and/or comments are very welcome, as always.

Thanks for the patience to read this longish post. :-)

So long,
Matthias

[1] https://github.com/magit/magit/issues/2915

-- 
Dipl.-Inf. (FH) Matthias Dahl | Software Engineer | binary-island.eu

[-- Warning: decoded text below may be mangled, UTF-8 assumed --]
[-- Attachment #2: 0001-Add-process-output-read-accounting.patch --]
[-- Type: text/x-patch; name="0001-Add-process-output-read-accounting.patch", Size: 1625 bytes --]

From 6c24b8d7082222df28d2046bfe70ff0e22342f08 Mon Sep 17 00:00:00 2001
From: Matthias Dahl <matthias.dahl@binary-island.eu>
Date: Tue, 24 Oct 2017 15:55:53 +0200
Subject: [PATCH 1/2] Add process output read accounting

This tracks the bytes read from a process's stdin which is not used
anywhere yet but required for follow-up work.
* src/process.c (read_process_output): Track bytes read from a process.
* src/process.h (struct Lisp_Process): Add infd_num_bytes_read
to track bytes read from a process.
---
 src/process.c | 2 ++
 src/process.h | 2 ++
 2 files changed, 4 insertions(+)

diff --git a/src/process.c b/src/process.c
index fc46e74332..904ca60863 100644
--- a/src/process.c
+++ b/src/process.c
@@ -5900,6 +5900,8 @@ read_process_output (Lisp_Object proc, int channel)
   /* Now set NBYTES how many bytes we must decode.  */
   nbytes += carryover;
 
+  p->infd_num_bytes_read += nbytes;
+
   odeactivate = Vdeactivate_mark;
   /* There's no good reason to let process filters change the current
      buffer, and many callers of accept-process-output, sit-for, and
diff --git a/src/process.h b/src/process.h
index 5a044f669f..f796719a51 100644
--- a/src/process.h
+++ b/src/process.h
@@ -129,6 +129,8 @@ struct Lisp_Process
     pid_t pid;
     /* Descriptor by which we read from this process.  */
     int infd;
+    /* Byte-count for process output read from `infd'.  */
+    unsigned long infd_num_bytes_read;
     /* Descriptor by which we write to this process.  */
     int outfd;
     /* Descriptors that were created for this process and that need
-- 
2.14.3


[-- Warning: decoded text below may be mangled, UTF-8 assumed --]
[-- Attachment #3: 0002-src-process.c-wait_reading_process_output-Fix-wait_p.patch --]
[-- Type: text/x-patch; name="0002-src-process.c-wait_reading_process_output-Fix-wait_p.patch", Size: 3155 bytes --]

From 57e9adc220312681588180aff2bae1eb07925ad5 Mon Sep 17 00:00:00 2001
From: Matthias Dahl <matthias.dahl@binary-island.eu>
Date: Tue, 24 Oct 2017 15:56:47 +0200
Subject: [PATCH 2/2] * src/process.c (wait_reading_process_output): Fix
 wait_proc hang.

If called recursively (through timers or process filters by the means
of accept-process-output), it is possible that the output of wait_proc
has already been read by one of those recursive calls, leaving the
original call hanging forever if no further output arrives through
that fd and no timeout has been specified. Implement proper checks by
taking advantage of the process output read accounting.
---
 src/process.c | 23 ++++++++++++++++++++++-
 1 file changed, 22 insertions(+), 1 deletion(-)

diff --git a/src/process.c b/src/process.c
index 904ca60863..a743aa973e 100644
--- a/src/process.c
+++ b/src/process.c
@@ -5003,6 +5003,8 @@ wait_reading_process_output (intmax_t time_limit, int nsecs, int read_kbd,
   struct timespec got_output_end_time = invalid_timespec ();
   enum { MINIMUM = -1, TIMEOUT, INFINITY } wait;
   int got_some_output = -1;
+  unsigned long initial_wait_proc_num_bytes_read = (wait_proc) ?
+                                                   wait_proc->infd_num_bytes_read : 0;
 #if defined HAVE_GETADDRINFO_A || defined HAVE_GNUTLS
   bool retry_for_async;
 #endif
@@ -5161,6 +5163,17 @@ wait_reading_process_output (intmax_t time_limit, int nsecs, int read_kbd,
 	      && requeued_events_pending_p ())
 	    break;
 
+          /* Timers could have called `accept-process-output', thus reading the output
+             of wait_proc while we (in the worst case) wait endlessly for it to become
+             available later. So we need to check if data has been read and break out
+             early if that is so since our job has been fulfilled. */
+          if (wait_proc
+              && wait_proc->infd_num_bytes_read != initial_wait_proc_num_bytes_read)
+            {
+              got_some_output = 1;
+              break;
+            }
+
           /* This is so a breakpoint can be put here.  */
           if (!timespec_valid_p (timer_delay))
               wait_reading_process_output_1 ();
@@ -5606,7 +5619,15 @@ wait_reading_process_output (intmax_t time_limit, int nsecs, int read_kbd,
 		 buffered-ahead character if we have one.  */
 
 	      nread = read_process_output (proc, channel);
-	      if ((!wait_proc || wait_proc == XPROCESS (proc))
+
+              /* In case a filter was run that called `accept-process-output', it is
+                 possible that the output from wait_proc was already read, leaving us
+                 waiting for it endlessly (if no timeout was specified). Thus, we need
+                 to check if data was already read. */
+              if (wait_proc
+                  && wait_proc->infd_num_bytes_read != initial_wait_proc_num_bytes_read)
+                got_some_output = 1;
+	      else if ((!wait_proc || wait_proc == XPROCESS (proc))
 		  && got_some_output < nread)
 		got_some_output = nread;
 	      if (nread > 0)
-- 
2.14.3


^ permalink raw reply related	[flat|nested] 151+ messages in thread

end of thread, other threads:[~2018-09-10  8:21 UTC | newest]

Thread overview: 151+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2017-10-24 18:52 wait_reading_process_ouput hangs in certain cases (w/ patches) Matthias Dahl
2017-10-25 14:53 ` Eli Zaretskii
2017-10-26 14:07   ` Matthias Dahl
2017-10-26 16:23     ` Eli Zaretskii
2017-10-26 18:56       ` Matthias Dahl
2017-10-28  8:20         ` Matthias Dahl
2017-10-28  9:28         ` Eli Zaretskii
2017-10-30  9:48           ` Matthias Dahl
2017-11-03  8:52             ` Matthias Dahl
2017-11-03  9:58               ` Eli Zaretskii
2017-11-04 12:11             ` Eli Zaretskii
2017-11-06 14:15               ` Matthias Dahl
2017-11-06 16:34                 ` Eli Zaretskii
2017-11-06 18:24                   ` Paul Eggert
2017-11-06 20:17                     ` Eli Zaretskii
2017-11-07 14:18                   ` Matthias Dahl
2017-11-07 16:40                     ` Eli Zaretskii
2017-11-10 14:45                       ` Matthias Dahl
2017-11-10 15:25                         ` Eli Zaretskii
2017-11-12 21:17                         ` Paul Eggert
2017-11-13  3:27                           ` Eli Zaretskii
2017-11-13  5:27                             ` Paul Eggert
2017-11-13 16:00                               ` Eli Zaretskii
2017-11-13 19:42                                 ` Paul Eggert
2017-11-13 20:12                                   ` Eli Zaretskii
2017-11-13 14:13                           ` Matthias Dahl
2017-11-13 16:10                             ` Eli Zaretskii
2017-11-14 15:05                               ` Matthias Dahl
2017-11-13 19:44                             ` Paul Eggert
2017-11-14 14:58                               ` Matthias Dahl
2017-11-14 15:24                                 ` Paul Eggert
2017-11-14 16:03                                   ` Eli Zaretskii
2017-11-14 16:23                                     ` Eli Zaretskii
2017-11-14 21:54                                       ` Paul Eggert
2017-11-15 14:03                                         ` Matthias Dahl
2017-11-16 15:37                                           ` Eli Zaretskii
2017-11-16 16:46                                           ` Paul Eggert
2017-11-18 14:24                                             ` Matthias Dahl
2017-11-18 14:51                                               ` Eli Zaretskii
2017-11-18 17:14                                                 ` Stefan Monnier
2017-11-19  7:07                                               ` Paul Eggert
2017-11-19 15:42                                                 ` Eli Zaretskii
2017-11-19 17:06                                                   ` Paul Eggert
2017-11-20 15:29                                                 ` Matthias Dahl
2017-11-21 14:44                                                   ` Matthias Dahl
2017-11-21 21:31                                                     ` Clément Pit-Claudel
2017-11-22 14:14                                                       ` Matthias Dahl
2017-11-22  8:55                                                     ` Paul Eggert
2017-11-22 14:33                                                       ` Matthias Dahl
2017-11-24  2:31                                                         ` Stefan Monnier
2017-12-28 17:52                                                         ` Eli Zaretskii
2017-12-04  9:40                                                       ` Matthias Dahl
2018-02-13 14:25                                                         ` Matthias Dahl
2018-02-13 16:56                                                           ` Paul Eggert
2018-02-16 16:01                                                           ` Eli Zaretskii
2018-02-16 16:09                                                             ` Lars Ingebrigtsen
2018-02-16 16:54                                                               ` Lars Ingebrigtsen
2018-02-22 11:45                                                               ` andres.ramirez
2018-02-26 14:39                                                                 ` Matthias Dahl
2018-02-26 15:11                                                                   ` andrés ramírez
2018-02-26 15:17                                                                     ` Lars Ingebrigtsen
2018-02-26 15:29                                                                       ` andrés ramírez
2018-02-26 16:52                                                                         ` Daniel Colascione
2018-02-26 17:19                                                                           ` andrés ramírez
2018-02-26 17:24                                                                             ` Daniel Colascione
2018-02-27  1:53                                                                               ` Re: andrés ramírez
2018-02-27  9:15                                                                       ` wait_reading_process_ouput hangs in certain cases (w/ patches) Matthias Dahl
2018-02-27 12:01                                                                         ` Lars Ingebrigtsen
2018-02-27  9:11                                                                     ` Matthias Dahl
2018-02-27 11:54                                                                       ` andrés ramírez
2018-02-27 15:02                                                                         ` Matthias Dahl
2018-02-27 15:13                                                                           ` Lars Ingebrigtsen
2018-02-27 15:17                                                                             ` Matthias Dahl
2018-02-27 15:19                                                                               ` Lars Ingebrigtsen
2018-02-27 15:14                                                                         ` Matthias Dahl
2018-02-27 15:17                                                                           ` Lars Ingebrigtsen
2018-03-01 10:42                                                                           ` Lars Ingebrigtsen
2018-03-01 14:36                                                                             ` Matthias Dahl
2018-03-01 15:10                                                                               ` andrés ramírez
2018-03-01 16:30                                                                                 ` T.V Raman
2018-03-01 16:46                                                                                   ` andrés ramírez
2018-03-01 18:23                                                                                     ` T.V Raman
2018-03-01 19:13                                                                                     ` Eli Zaretskii
2018-03-02 20:21                                                                                       ` andrés ramírez
2018-03-03  7:55                                                                                         ` Eli Zaretskii
2018-03-05 14:43                                                                             ` Matthias Dahl
2018-03-05 14:44                                                                               ` Lars Ingebrigtsen
2018-03-05 14:54                                                                                 ` Matthias Dahl
2018-03-13  9:54                                                                                 ` Matthias Dahl
2018-03-13 12:35                                                                                   ` Robert Pluim
2018-03-13 13:40                                                                                     ` Robert Pluim
2018-03-13 15:10                                                                                     ` Matthias Dahl
2018-03-13 15:30                                                                                       ` Robert Pluim
2018-03-13 15:36                                                                                       ` Dmitry Gutov
2018-03-13 15:46                                                                                         ` Robert Pluim
2018-03-13 15:56                                                                                           ` Dmitry Gutov
2018-03-13 16:57                                                                                             ` Robert Pluim
2018-03-13 18:03                                                                                               ` Eli Zaretskii
2018-03-13 20:12                                                                                                 ` Robert Pluim
2018-03-14 14:21                                                                                         ` Matthias Dahl
2018-03-13 16:32                                                                                       ` Lars Ingebrigtsen
2018-03-14  9:32                                                                                         ` Matthias Dahl
2018-03-14 14:55                                                                                           ` Lars Ingebrigtsen
2018-03-31 15:44                                                                                       ` Lars Ingebrigtsen
2018-04-01  2:05                                                                                         ` andrés ramírez
2018-06-08  5:11                                                                                         ` Leo Liu
2018-06-08  6:57                                                                                           ` Eli Zaretskii
2018-06-08  9:07                                                                                             ` Leo Liu
2018-03-13 16:12                                                                                   ` Eli Zaretskii
2018-03-14  4:16                                                                                     ` Leo Liu
2018-03-14  9:22                                                                                       ` Robert Pluim
2018-03-15  0:37                                                                                         ` Leo Liu
2018-03-14 15:09                                                                                       ` andrés ramírez
2018-03-14 16:45                                                                                       ` Eli Zaretskii
2018-03-15  1:03                                                                                         ` Leo Liu
2018-03-15  7:55                                                                                           ` Robert Pluim
2018-03-14 22:54                                                                                       ` Stefan Monnier
2018-03-15  1:06                                                                                         ` Leo Liu
2018-03-14  9:56                                                                                     ` Matthias Dahl
2018-03-14 12:24                                                                                       ` Stefan Monnier
2018-03-14 14:34                                                                                         ` Matthias Dahl
2018-03-14 22:52                                                                                           ` Stefan Monnier
2018-03-15 15:17                                                                                             ` Matthias Dahl
2018-03-14 16:43                                                                                       ` Eli Zaretskii
2018-03-15 14:59                                                                                         ` Matthias Dahl
2018-06-26 13:36                                                                                           ` Matthias Dahl
2018-06-26 14:09                                                                                             ` andrés ramírez
2018-06-27 13:10                                                                                               ` Matthias Dahl
2018-06-27 15:18                                                                                                 ` Eli Zaretskii
2018-06-28  8:01                                                                                                   ` Matthias Dahl
2018-06-28 13:04                                                                                                     ` Eli Zaretskii
2018-06-28 13:25                                                                                                       ` Matthias Dahl
2018-06-28 16:33                                                                                                         ` Leo Liu
2018-06-28 18:31                                                                                                           ` T.V Raman
2018-07-02 13:27                                                                                                             ` Matthias Dahl
2018-07-02 14:35                                                                                                               ` T.V Raman
2018-07-03 13:27                                                                                                                 ` Matthias Dahl
2018-07-03 13:52                                                                                                                   ` T. V. Raman
2018-07-03 15:03                                                                                                                     ` Stefan Monnier
2018-07-02 13:24                                                                                                           ` Matthias Dahl
2018-07-14  2:27                                                                                                             ` Leo Liu
2018-07-03 13:34                                                                                                       ` Matthias Dahl
2018-07-03 18:57                                                                                                         ` Eli Zaretskii
2018-07-04  7:35                                                                                                           ` Matthias Dahl
2018-07-04 15:11                                                                                                             ` Eli Zaretskii
2018-07-21  9:52                                                                                             ` Eli Zaretskii
2018-08-07  8:38                                                                                               ` Matthias Dahl
2018-08-07 17:10                                                                                                 ` Paul Eggert
2018-09-10  8:21                                                                                                 ` Eli Zaretskii
2017-11-07 17:23                     ` Stefan Monnier
2017-11-10 14:53                       ` Matthias Dahl

Code repositories for project(s) associated with this public inbox

	https://git.savannah.gnu.org/cgit/emacs.git

This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for read-only IMAP folder(s) and NNTP newsgroup(s).