bug#84: Acknowledgement (23.0.60; Occasional hangs in flyspell-mode and ispell-word)

bug#84: Acknowledgement (23.0.60; Occasional hangs in flyspell-mode and ispell-word)

[Markus Triska]

Here's a test case which I think illustrates part of the problem: Let
hang.el contain only the form:

   (with-temp-buffer
     (insert "test")
     (let ((n 0))
       (while t
         (setq n (1+ n))
         (when (= (mod n 1000) 0)
           (message "%s" (emacs-uptime)))
         (condition-case err
             (ispell-word nil t)
           (error (message "error: %s" err))))))

and do:

   $ emacs -Q --script hang.el

This continuously spell-checks the word "test". In another terminal,
kill the aspell process:

   $ killall -s 9 aspell

Different things can then happen to the Emacs process, depending on its
exact state when you kill aspell:

a) error: (error SIGPIPE raised on process ispell; closed it)

b) error: (error Process ispell not running)

c) Emacs hangs, waiting for more output from aspell

In cases (a) and (b), Emacs continues as normal after it has
automatically restarted aspell. Case (c) seems to be part of the
original problem, which I think can happen as follows: Aspell crashes
while flyspell-word waits for output; one can interrupt the wait with
C-g, but because no error was risen, flyspell-post-command-hook is not
removed from post-command-hook, and is still triggered after each
command (including pressing C-g itself), thus resulting in new waits.

Thus, instead of waiting for more output from a dead process, doesn't an
error seem preferable?

bug#84: Acknowledgement (23.0.60; Occasional hangs in flyspell-mode and ispell-word)

[Markus Triska]

> while flyspell-word waits for output; one can interrupt the wait with
> C-g

I've now seen that this wasn't the case in the backtrace, i.e., I
specifically could NOT interrupt accept-process-output; also, had I been
able to interrupt it, a subsequent process-send-string to the dead
process from flyspell-word would have triggered an error and thus
removed flyspell-post-command-hook from post-command-hook.

To sum up, I think it remains valid that accept-process-output should
throw an error (instead of waiting, as it currently does) if the process
it is waiting for is dead, and an independent issue is that
wait_reading_process_output can sometimes not be interrupted manually
and can make Emacs hang indefinitely. So far, the hangs seem to occur
when I have previously interrupted wait_reading_process_output when it
was waiting for output from a dead process. For example, I'm using the
following to enable flyspell mode when it was disabled:

   (defun reactivate-flyspell ()
     (unless (memq 'flyspell-post-command-hook post-command-hook)
       (flyspell-mode 1)))

   (setq my-idle (run-with-idle-timer 0.1 t 'reactivate-flyspell))

then I continuously kill aspell with:

   $ while true; do killall -s 9 aspell; sleep 0.1; done

Then I go into a buffer with a lot of text and move the cursor over a
few words (to flyspell-them) until Emacs hangs due to
accept-process-output from a dead aspell process. I can always interrupt
this with C-g. I do this a few times, then stop the continuous killing
of aspell, and then start Gnus a few times. This almost always makes
Emacs hang completely; I'm now trying to make this test case shorter.

bug#84: Acknowledgement (23.0.60; Occasional hangs in flyspell-mode and ispell-word)

[Markus Triska]

> of aspell, and then start Gnus a few times. This almost always makes
> Emacs hang completely; I'm now trying to make this test case shorter.

I now have a precise test case that makes Emacs totally hang on my
machine every time:

(1) With M-:, I evaluate the following forms in "emacs -Q":

   (defmacro preserve-message (form)
     `(let ((msg (current-message)))
        ,form
        (message "%s" msg)))

   (let ((n 0))
     (while (< n 10)
       (with-timeout (1 (setq n (1+ n)) (message "# timeouts: %s" n))
         (condition-case err
             (with-temp-buffer
               (insert "test")
               (preserve-message
                (ispell-word nil t)))
           (error (message "error: %s" err))))))

(2) In a separate terminal, I continuously kill the aspell process:

    while true; do killall -9 aspell; sleep 0.1; done

(3) I wait until the timeout counter has reached 10, i.e., evaluation
    of the second form above is finished, then I evaluate the forms:

   (defun reactivate-flyspell ()
     (unless (memq 'flyspell-post-command-hook post-command-hook)
       (preserve-message
        (flyspell-mode 1))))

   (setq my-idle (run-with-idle-timer 0.1 t 'reactivate-flyspell))

(4) Then I enter and exit Gnus three times:

    M-x gnus RET q y
    M-x gnus RET q y
    M-x gnus RET q y

    all while aspell is constantly killed and restarted in the
    background. Starting Gnus only once does not suffice.

(5) I kill the shell script, so aspell can now run interruptedly. I
    enter and try to exit Gnus again:

    M-x gnus RET q y

    and Emacs hangs completely. I cannot interrupt it with C-g. The
    backtrace follows.

This is with GNU Emacs 23.0.60.1 (i386-apple-darwin8.11.1, GTK+ Version
2.12.9) of 2008-06-29; I will try to reproduce it with different
machines later. You may have to adjust the sleep time in the shell
command to kill the aspell process not too often.


   #0  0x9000177e in __error ()
   #1  0x9000172b in cthread_set_errno_self ()
   #2  0x9011078b in cerror ()
   #3  0x00181918 in read_process_output (proc=42226388, channel=0) at process.c:5322
   #4  0x00188134 in wait_reading_process_output (time_limit=0, microsecs=0, read_kbd=0, do_display=0, wait_for_cell=58721289, wait_proc=0x28452d0, just_wait_proc=0) at process.c:4772
   #5  0x00188f38 in Faccept_process_output (process=42226388, seconds=58721289, millisec=58721289, just_this_one=58721289) at process.c:4252
   #6  0x00144ac4 in Ffuncall (nargs=2, args=0xbfffec60) at eval.c:3052
   #7  0x0017dc57 in Fbyte_code (bytestr=58983403, vector=35024692, maxdepth=2) at bytecode.c:678
   #8  0x00143f72 in Feval (form=40259517) at eval.c:2383
   #9  0x0014655b in internal_lisp_condition_case (var=58721289, bodyform=40259517, handlers=40289301) at eval.c:1456
   #10 0x0017cb8d in Fbyte_code (bytestr=58985659, vector=35024820, maxdepth=5) at bytecode.c:868
   #11 0x001443a7 in funcall_lambda (fun=35025140, nargs=0, arg_vector=0xbffff014) at eval.c:3229
   #12 0x0014488a in Ffuncall (nargs=1, args=0xbffff010) at eval.c:3099
   #13 0x0017dc57 in Fbyte_code (bytestr=58738651, vector=35023668, maxdepth=4) at bytecode.c:678
   #14 0x001443a7 in funcall_lambda (fun=35023860, nargs=0, arg_vector=0xbffff1f0) at eval.c:3229
   #15 0x0014488a in Ffuncall (nargs=1, args=0xbffff1ec) at eval.c:3099
   #16 0x00145e14 in run_hook_with_args (nargs=1, args=0xbffff1ec, cond=to_completion) at eval.c:2701
   #17 0x00145f9c in Frun_hooks (nargs=1, args=0xbffff2a4) at eval.c:2564
   #18 0x00144a2f in Ffuncall (nargs=2, args=0xbffff2a0) at eval.c:3023
   #19 0x00145c9f in call1 (fn=58809001, arg1=58751489) at eval.c:2827
   #20 0x000d6434 in safe_run_hooks_1 (hook=-1073745176) at keyboard.c:2152
   #21 0x00142c1c in internal_condition_case (bfun=0xd6402 <safe_run_hooks_1>, handlers=58721337, hfun=0xd643e <safe_run_hooks_error>) at eval.c:1511
   #22 0x000d5ac5 in safe_run_hooks (hook=58751489) at keyboard.c:2180
   #23 0x000e3d46 in command_loop_1 () at keyboard.c:1929
   #24 0x00142c1c in internal_condition_case (bfun=0xe387e <command_loop_1>, handlers=58760929, hfun=0xdc6d9 <cmd_error>) at eval.c:1511
   #25 0x000d5830 in command_loop_2 () at keyboard.c:1367
   #26 0x0014286e in internal_catch (tag=58757001, func=0xd57ec <command_loop_2>, arg=58721289) at eval.c:1247
   #27 0x000d55d2 in command_loop () at keyboard.c:1346
   #28 0x000d568b in recursive_edit_1 () at keyboard.c:955
   #29 0x000d57d3 in Frecursive_edit () at keyboard.c:1017
   #30 0x000d4813 in main (argc=3, argv=0xbffff820) at emacs.c:1762
    
   (gdb) bt full
   #0  0x9000177e in __error ()
   No symbol table info available.
   #1  0x9000172b in cthread_set_errno_self ()
   No symbol table info available.
   #2  0x9011078b in cerror ()
   No symbol table info available.
   #3  0x00181918 in read_process_output (proc=42226388, channel=0) at process.c:5322
           nbytes = -1
           outstream = 0
           old = (struct buffer *) 0x21872d0
           p = (struct Lisp_Process *) 0x28452d0
           opoint = 0
           coding = (struct coding_system *) 0x284f040
           carryover = 3289392
   #4  0x00188134 in wait_reading_process_output (time_limit=0, microsecs=0, read_kbd=0, do_display=0, wait_for_cell=58721289, wait_proc=0x28452d0, just_wait_proc=0) at process.c:4772
           nread = -1610559488
           total_nread = 0
           timeout_reduced_for_timers = 0
           channel = -1146
           nfds = -1
           Available = {
     fds_bits = {0 <repeats 32 times>}
   }
           Connecting = {
     fds_bits = {0 <repeats 32 times>}
   }
           check_connect = 0
           check_delay = 0
           no_avail = 1
           xerrno = 134678021
           proc = 42226388
           timeout = {
     tv_sec = 100000, 
     tv_usec = 0
   }
           end_time = {
     tv_sec = -1879027210, 
     tv_usec = 13
   }
           wait_channel = 0
           got_some_input = 0
   #5  0x00188f38 in Faccept_process_output (process=42226388, seconds=58721289, millisec=58721289, just_this_one=58721289) at process.c:4252
           secs = 0
           usecs = 0
           process = 42226388
           seconds = -1879042283
           millisec = 0
   #6  0x00144ac4 in Ffuncall (nargs=2, args=0xbfffec60) at eval.c:3052
           fun = -1073746976
           original_fun = 3069896
           funcar = -1879042283
           numargs = 1
           val = -1879042184
           backtrace = {
     next = 0xbfffed74, 
     function = 0xbfffec60, 
     args = 0xbfffec64, 
     nargs = 1, 
     evalargs = 0 '\0', 
     debug_on_exit = 0 '\0'
   }
           internal_args = (Lisp_Object *) 0xbfffebe0
           i = -1879042283
           args = (Lisp_Object *) 0x2ed7c8
   #7  0x0017dc57 in Fbyte_code (bytestr=58983403, vector=35024692, maxdepth=2) at bytecode.c:678
           op = -1610559488
           vectorp = (Lisp_Object *) 0x2166f38
           stack = {
     pc = 0x5992b35 "?\n@Ř?\002", 
     top = 0xbfffec64, 
     bottom = 0xbfffec60, 
     byte_string = 58983403, 
     byte_string_start = 0x5992b30 "?\030?\t!?\n@Ř?\002", 
     constants = 35024692, 
     next = 0xbfffef04
   }
           result = -1879042184
           bytestr = -1879042283
   #8  0x00143f72 in Feval (form=40259517) at eval.c:2383
           numargs = -1879042283
           argvals = {58983403, 35024692, 16, 1, 0, 1026674, 1323343, 58983451}
           args_left = 58721289
           i = 3
           fun = -1879042184
           val = -1879042184
           original_fun = 58832137
           original_args = 40259525
           funcar = -1879042283
           backtrace = {
     next = 0xbfffefcc, 
     function = 0xbfffed8c, 
     args = 0xbfffed54, 
     nargs = 3, 
     evalargs = 1 '\001', 
     debug_on_exit = 0 '\0'
   }
           form = 58721289
   #9  0x0014655b in internal_lisp_condition_case (var=58721289, bodyform=40259517, handlers=40289301) at eval.c:1456
           val = -1879042283
           c = {
     tag = 58721289, 
     val = 58721289, 
     next = 0xbffff2d8, 
     gcpro = 0x0, 
     jmp = {895, 1569345, 8096, 1336252, 3, 1328852, 93923673, 58721289, -1073746328, -1073746512, 42205215, 658, 1336418, 95813655, 58720287, 31, -1073807360, 55}, 
     backlist = 0xbfffefcc, 
     handlerlist = 0xbffff34c, 
     lisp_eval_depth = 3, 
     pdlcount = 14, 
     poll_suppress_count = 1, 
     interrupt_input_blocked = 0, 
     byte_stack = 0xbfffef04
   }
           h = {
     handler = 40289301, 
     var = 58721289, 
     chosen_clause = -1073746300, 
     tag = 0xbfffedc8, 
     next = 0xbffff34c
   }
   #10 0x0017cb8d in Fbyte_code (bytestr=58985659, vector=35024820, maxdepth=5) at bytecode.c:868
           handlers = -1610559488
           body = -1879042283
           op = -1610559488
           vectorp = (Lisp_Object *) 0x2166fb8
           stack = {
     pc = 0x5992959 "?\016&A?\026&??", 
     top = 0xbfffee80, 
     bottom = 0xbfffee80, 
     byte_string = 58985659, 
     byte_string_start = 0x599286c "? ??? ?`\030?\t!\032ɉ\033\034ɉ\035\036%?\036&\n?=?,", 
     constants = 35024820, 
     next = 0xbffff084
   }
           result = -1879042184
           bytestr = -1879042283
   #11 0x001443a7 in funcall_lambda (fun=35025140, nargs=0, arg_vector=0xbffff014) at eval.c:3229
           val = -1610559488
           syms_left = 35025136
           next = 35025136
           i = 0
           optional = 1
           rest = 0
   #12 0x0014488a in Ffuncall (nargs=1, args=0xbffff010) at eval.c:3099
           fun = 35025140
           original_fun = 94138233
           funcar = -1879042283
           numargs = 0
           val = -1879042184
           backtrace = {
     next = 0xbffff14c, 
     function = 0xbffff010, 
     args = 0xbffff014, 
     nargs = 0, 
     evalargs = 0 '\0', 
     debug_on_exit = 0 '\0'
   }
           internal_args = (Lisp_Object *) 0x21670f4
           i = -1879042283
           args = (Lisp_Object *) 0x59c6f79
   #13 0x0017dc57 in Fbyte_code (bytestr=58738651, vector=35023668, maxdepth=4) at bytecode.c:678
           op = -1610559488
           vectorp = (Lisp_Object *) 0x2166b38
           stack = {
     pc = 0x59926b4 "?p\025`\026\017?;", 
     top = 0xbffff010, 
     bottom = 0xbffff010, 
     byte_string = 58738651, 
     byte_string_start = 0x5992698 "\b?\031\032? ?\025", 
     constants = 35023668, 
     next = 0x0
   }
           result = -1879042184
           bytestr = -1879042283
   #14 0x001443a7 in funcall_lambda (fun=35023860, nargs=0, arg_vector=0xbffff1f0) at eval.c:3229
           val = -1610559488
           syms_left = 35023856
           next = 35023856
           i = 0
           optional = 2
           rest = 1248273
   #15 0x0014488a in Ffuncall (nargs=1, args=0xbffff1ec) at eval.c:3099
           fun = 35023860
           original_fun = 93950897
           funcar = -1879042283
           numargs = 0
           val = -1879042184
           backtrace = {
     next = 0xbffff24c, 
     function = 0xbffff1ec, 
     args = 0xbffff1f0, 
     nargs = 0, 
     evalargs = 0 '\0', 
     debug_on_exit = 0 '\0'
   }
           internal_args = (Lisp_Object *) 0x2166bf4
           i = -1879042283
           args = (Lisp_Object *) 0x59993b1
   #16 0x00145e14 in run_hook_with_args (nargs=1, args=0xbffff1ec, cond=to_completion) at eval.c:2701
           sym = 58751489
           val = -1879042184
           ret = 58721289
           globals = -1879042283
   #17 0x00145f9c in Frun_hooks (nargs=1, args=0xbffff2a4) at eval.c:2564
           hook = {93950897}
           i = 0
           nargs = 1
   #18 0x00144a2f in Ffuncall (nargs=2, args=0xbffff2a0) at eval.c:3023
           fun = 3063148
           original_fun = -1073745244
           funcar = -1879042283
           numargs = 1
           val = -1879042184
           backtrace = {
     next = 0x0, 
     function = 0xbffff2a0, 
     args = 0xbffff2a4, 
     nargs = 1, 
     evalargs = 0 '\0', 
     debug_on_exit = 0 '\0'
   }
           internal_args = (Lisp_Object *) 0x2ebd6c
           i = -1879042283
           args = (Lisp_Object *) 0xbffff2a4
   #19 0x00145c9f in call1 (fn=58809001, arg1=58751489) at eval.c:2827
           ret_ungc_val = -1610559488
   #20 0x000d6434 in safe_run_hooks_1 (hook=-1073745176) at keyboard.c:2152
   No locals.
   #21 0x00142c1c in internal_condition_case (bfun=0xd6402 <safe_run_hooks_1>, handlers=58721337, hfun=0xd643e <safe_run_hooks_error>) at eval.c:1511
           val = -1879042283
           c = {
     tag = 58721289, 
     val = 58721289, 
     next = 0xbffff498, 
     gcpro = 0x0, 
     jmp = {895, 1250071, 8096, 1321771, -1073745096, 1250219, 3307312, 2, -1073745032, -1073745216, 94961695, 662, 1321920, 1245207, 31, 31, 0, 1310775}, 
     backlist = 0x0, 
     handlerlist = 0xbffff50c, 
     lisp_eval_depth = 0, 
     pdlcount = 3, 
     poll_suppress_count = 1, 
     interrupt_input_blocked = 0, 
     byte_stack = 0x0
   }
           h = {
     handler = 58721337, 
     var = 58721289, 
     chosen_clause = 58807000, 
     tag = 0xbffff2d8, 
     next = 0xbffff50c
   }
   #22 0x000d5ac5 in safe_run_hooks (hook=58751489) at keyboard.c:2180
           hook = -1610559488
   #23 0x000e3d46 in command_loop_1 () at keyboard.c:1929
           cmd = 3284528
           lose = 3284528
           nonundocount = 0
           keybuf = {904, 40, 3307184, 58721289, -1073744776, 903096, 34397045, -1073744850, -1073744808, -1879037169, 92274892, 152, -1073744850, 58721289, 100663439, 1, 31, -1879036413, 51396120, 58721337, 51385976, -1881082098, 5625428, 0, -1073744804, -1073744992, 0, 3342336, 58721289, 67060025}
           i = 1
           prev_modiff = 138
           prev_buffer = (struct buffer *) 0x284f270
           already_adjusted = 0
   #24 0x00142c1c in internal_condition_case (bfun=0xe387e <command_loop_1>, handlers=58760929, hfun=0xdc6d9 <cmd_error>) at eval.c:1511
           val = -1879042283
           c = {
     tag = 58721289, 
     val = 58721289, 
     next = 0xbffff59c, 
     gcpro = 0x0, 
     jmp = {895, 17831856, 8096, 1321771, 58721289, 58721289, 3297712, 3284528, -1073744584, -1073744768, 31, 658, 1321920, 1507351, 3276831, 3276831, -1073807360, -1073807305}, 
     backlist = 0x0, 
     handlerlist = 0x0, 
     lisp_eval_depth = 0, 
     pdlcount = 2, 
     poll_suppress_count = 1, 
     interrupt_input_blocked = 0, 
     byte_stack = 0x0
   }
           h = {
     handler = 58760929, 
     var = 58721289, 
     chosen_clause = 58721337, 
     tag = 0xbffff498, 
     next = 0x0
   }
   #25 0x000d5830 in command_loop_2 () at keyboard.c:1367
           val = -1610559488
   #26 0x0014286e in internal_catch (tag=58757001, func=0xd57ec <command_loop_2>, arg=58721289) at eval.c:1247
           c = {
     tag = 58757001, 
     val = 58721289, 
     next = 0x0, 
     gcpro = 0x0, 
     jmp = {895, 15, 8096, 1320914, 2, 20367, 3306688, 3284528, -1073744360, -1073744512, 58851359, 658, 1321057, 58851351, 58851359, 58720287, 51380224, 55}, 
     backlist = 0x0, 
     handlerlist = 0x0, 
     lisp_eval_depth = 0, 
     pdlcount = 2, 
     poll_suppress_count = 1, 
     interrupt_input_blocked = 0, 
     byte_stack = 0x0
   }
           tag = -1610559488
   #27 0x000d55d2 in command_loop () at keyboard.c:1346
           val = -1610559488
   #28 0x000d568b in recursive_edit_1 () at keyboard.c:955
           val = 0
   #29 0x000d57d3 in Frecursive_edit () at keyboard.c:1017
           buffer = 58721289
   #30 0x000d4813 in main (argc=3, argv=0xbffff820) at emacs.c:1762
           dummy = -1881117246
           stack_bottom_variable = 0 '\0'
           do_initial_setlocale = 1
           skip_args = 0
           rlim = {
     rlim_cur = 8388608, 
     rlim_max = 67108864
   }
           no_loadup = 0
           junk = 0x0

bug#84: Acknowledgement (23.0.60; Occasional hangs in flyspell-mode and ispell-word)

[Markus Triska]

The following patch fixes the problem for me:


2008-07-10  Markus Triska  <markus.triska@gmx.at>

        * process.c (wait_reading_process_output): handle EBADF


diff --git a/src/process.c b/src/process.c
index e8d0090..0cf04bc 100644
--- a/src/process.c
+++ b/src/process.c
@@ -4791,6 +4791,10 @@ wait_reading_process_output (time_limit, microsecs, read_kbd, do_display,
 	      else if (nread == -1 && EWOULDBLOCK == errno)
                 break;
 #endif
+#ifdef EBADF
+	      else if (nread == -1 && EBADF == errno)
+		break;
+#endif
 	    }
 	  if (total_nread > 0 && do_display)
 	    redisplay_preserve_echo_area (10);

bug#84: Acknowledgement (23.0.60; Occasional hangs in flyspell-mode and ispell-word)

[Markus Triska]

I now think the previous patch only fixes a symptom of an underlying
problem, which is that the aspell process occasionally receives SIGPIPE
and terminates unexpectedly. Here's a simpler test case - it seems to
work only on OSX and with Emacs >= 23, but I have seen very similar
problems on other systems and with Emacs <= 22 too (for example, when
replying to a post in Gnus, sometimes aspell would die and not be
restarted). Let f.el consist of:

   (defun reactivate-flyspell ()
     (unless (memq 'flyspell-post-command-hook post-command-hook)
       (flyspell-mode 1)))

   (setq my-idle (run-with-idle-timer 0.1 t 'reactivate-flyspell))

If I then do:

1) $ emacs -Q f.el -f eval-buffer

2) enter and leave Gnus twice: M-x gnus RET q y M-x gnus RET q y

3) kill the aspell process:
   
   M-! killall -9 aspell RET

   (aspell is instantly restarted by the idle timer, and you can attach
    gdb to the new process to verify the signal in the next step.)
   
4) M-x gnus RET q y  (==> you're back in f.el - do anything, like C-n)

   Now aspell receives SIGPIPE and exits, and I get EBADF in
   wait_reading_process_output; the previous patch handles this, and
   thus you can at least interrupt the wait. Ideally though, the aspell
   process would not have been killed in the first place, and besides,
   after SIGPIPE, the process status should become 'signal eventually.

I would like to trace down where the SIGPIPE comes from, and how the
file descriptor can become invalid in Emacs; I've traced through the
Lisp code of Gnus and flyspell/ispell, and they seem not to touch the
aspell process here.  What would be a good place to put a breakpoint in
GDB, such that I can observe execution right after the final "C-n" in
f.el?  I tried to raise an error in before-change-functions in f.el, and
instead of "C-n" insert a character in the last step, so that I can put
a breakpoint in Fsignal, but the SIGPIPE occurs before this hook.