bug#17561: Emacs can forget processes

[Jorgen Schaefer]

On Sat, 24 May 2014 16:01:20 -0700
Paul Eggert <eggert@cs.ucla.edu> wrote:

> Jorgen Schaefer wrote:
> 
> >> Can you run the shell command 'strace -p' on an Emacs with the
> >> problem, and trace the system calls near the offending area?
> >
> > The bug report includes an strace output. Emacs does the pselect6
> > call
> 
> Sorry, I should have been more specific.  It'd be nice to see the
> strace output for when you run start-process in a temp buffer, not
> for later when Emacs is in a tight loop.

Oh, my bad. Luckily, the bug just occurred again (it's really non-
deterministic):

strace -fttT output

The trace starts with a number of these triplets, which seem to be
"Emacs behaving normally". After terminating the process and returning
to "normal" later, Emacs does not issue these rt_sigprocmask calls
anymore, though.

16300 09:41:27.072717 pselect6(20, [3 4 5 6 8 10 14 15 19], [], NULL, {0, 
176410474}, {NULL, 8}) = 0 (Timeout) <0.176635>
16300 09:41:27.249649 rt_sigprocmask(SIG_BLOCK, [WINCH IO], NULL, 8) = 0 
<0.000011>
16300 09:41:27.249881 rt_sigprocmask(SIG_UNBLOCK, [WINCH IO], NULL, 8) = 0 
<0.000010>

Then there's a large bunch of syscalls related to my command to restart
the process, with the "\r" now being me sending the M-x command:

16300 09:41:28.298391 read(3, "\r", 1)  = 1 <0.000012>
16300 09:41:28.298438 ioctl(3, FIONREAD, [0]) = 0 <0.000009>
16300 09:41:28.298480 ioctl(3, FIONREAD, [0]) = 0 <0.000009>
16300 09:41:28.312476 write(3, "\r", 1) = 1 <0.000021>
16300 09:41:28.317392 kill(4294953129, SIGHUP) = 0 <0.002235>
16300 09:41:28.321642 rt_sigprocmask(SIG_BLOCK, [WINCH IO], NULL, 8) = 0 
<0.000017>
16300 09:41:28.321841 write(3, "\33[K\33[H\n\n", 8) = 8 <0.000018>
16300 09:41:28.321909 rt_sigprocmask(SIG_UNBLOCK, [WINCH IO], NULL, 8) = 0 
<0.000012>
16300 09:41:28.321975 --- SIGIO (I/O possible) @ 0 (0) ---
16300 09:41:28.322004 rt_sigreturn(0x1d) = 0 <0.000013>
16300 09:41:28.322056 ioctl(3, FIONREAD, [0]) = 0 <0.000014>
16300 09:41:28.322183 ioctl(3, FIONREAD, [0]) = 0 <0.000012>
16300 09:41:28.322253 pselect6(20, [3 4 5 6 8 10 14 15 19], [], NULL, {0, 
499801124}, {NULL, 8}) = 1 (in [15], left {0, 499788244}) <0.000024>
16300 09:41:28.322337 read(15, "", 4096) = 0 <0.000012>
16300 09:41:28.322475 ioctl(3, FIONREAD, [0]) = 0 <0.000014>
16300 09:41:28.322533 pselect6(20, [3 4 5 6 8 10 14 15 19], [], NULL, {0, 
499519197}, {NULL, 8}) = 1 (in [15], left {0, 499513475}) <0.000017>
16300 09:41:28.322603 read(15, "", 4096) = 0 <0.000010>

Killing the process via the process list (hence the "d"):

16300 09:49:00.151571 read(3, "d", 1)   = 1 <0.000009>
16300 09:49:00.151604 ioctl(3, FIONREAD, [0]) = 0 <0.000007>
16300 09:49:00.151636 ioctl(3, FIONREAD, [0]) = 0 <0.000006>
16300 09:49:00.151790 rt_sigprocmask(SIG_BLOCK, [CHLD], [QUIT ALRM CHLD PROF], 
8) = 0 <0.000020>
16300 09:49:00.151849 kill(4294953129, SIGKILL) = 0 <0.000013>
16300 09:49:00.151896 rt_sigprocmask(SIG_SETMASK, [QUIT ALRM CHLD PROF], NULL, 
8) = 0 <0.000007>
16300 09:49:00.151964 close(12)         = 0 <0.000015>
16300 09:49:00.152003 close(15)         = 0 <0.000010>
16300 09:49:00.153389 rt_sigprocmask(SIG_BLOCK, [WINCH IO], NULL, 8) = 0 
<0.000010>
16300 09:49:00.153531 rt_sigprocmask(SIG_UNBLOCK, [WINCH IO], NULL, 8) = 0 
<0.000008>

> > read(2) returning 0 indicates an EOF (which pselect6 indicates as
> > waiting input), I suspect there could at least be a sanity check
> > here to close the file descriptors instead of continuously polling.
> 
> Maybe, though I worry that might mask the bug and might cause other, 
> more serious failures down the road.  It'd be nicer to fix the actual 
> bug, if we can figure out what it is.
> 
> For what it's worth I tried reproducing the bug with emacs-24 'emacs
> -Q' on Fedora, using your recipe, but this didn't have a problem.  I
> ran it 1000 times rapidly in sequence and it was OK.  I ran it 10000
> times and ran out of file descriptors but that's to be expected.

Yes, the bug is really random. I have not been able to intentionally
reproduce it. It just happens once in a while. Until this bug report,
I wasn't even sure what was causing my Emacs to stop responding in the
first place. It just happened, once every few days, that Emacs suddenly
becomes very sluggish.

My Emacs sessions usually have a number of processes open. When the bug
showed up just now, it was five processes and three network connections,
for example. I'm not sure if that's related.

Regards,
Jorgen