GNU bug report logs - #17647
24.4.50; accept-process-output with process nil can miss output

Previous Next

Package: emacs;

Reported by: Jorgen Schaefer <forcer <at> forcix.cx>

Date: Fri, 30 May 2014 22:26:01 UTC

Severity: normal

Found in version 24.4.50

Done: Paul Eggert <eggert <at> cs.ucla.edu>

Bug is archived. No further changes may be made.

To add a comment to this bug, you must first unarchive it, by sending
a message to control AT debbugs.gnu.org, with unarchive 17647 in the body.
You can then email your comments to 17647 AT debbugs.gnu.org in the normal way.

Toggle the display of automated, internal messages from the tracker.

View this report as an mbox folder, status mbox, maintainer mbox


Report forwarded to bug-gnu-emacs <at> gnu.org:
bug#17647; Package emacs. (Fri, 30 May 2014 22:26:01 GMT) Full text and rfc822 format available.

Acknowledgement sent to Jorgen Schaefer <forcer <at> forcix.cx>:
New bug report received and forwarded. Copy sent to bug-gnu-emacs <at> gnu.org. (Fri, 30 May 2014 22:26:02 GMT) Full text and rfc822 format available.

Message #5 received at submit <at> debbugs.gnu.org (full text, mbox):

From: Jorgen Schaefer <forcer <at> forcix.cx>
To: bug-gnu-emacs <at> gnu.org
Subject: 24.4.50; accept-process-output with process nil can miss output
Date: Sat, 31 May 2014 00:24:57 +0200
Hello!
I'm witnessing some weird behavior which I assume is some sort of race
condition. The following piece of code reliably hangs my running Emacs
for two seconds while `accept-process-output' is waiting for output,
while a freshly-start Emacs (same binary) returns immediately, as
the process indeed has emitted some output.

(with-temp-buffer
  (let ((proc (start-process "test" (current-buffer) "bash" "-c"
                             "echo foo ; sleep 5")))
    (set-process-query-on-exit-flag proc nil)
    (accept-process-output nil 2)))

This is with a recent trunk version of Emacs, but I have had someone
else with an Emacs 24.3 reproduce the behavior. It only happens in
Emacsen that have been running for a while, but I haven't been able to
trigger it deliberately.

It's interesting that passing the specific process with output to
`accept-process-output' does not exhibit this bug. The following piece
of code always returns immediately.

(with-temp-buffer
  (let ((proc (start-process "test" (current-buffer) "bash" "-c"
                             "echo foo ; sleep 5")))
    (set-process-query-on-exit-flag proc nil)
    (accept-process-output proc 2)))

This is the Emacs process exhibiting the problem:

00:04:34.316560 pselect6(16, [3 4 5 6 8 11 13 15], [], NULL, {0, 192669865}, {NULL, 8}) = 0 (Timeout) <0.192904>
00:04:34.509752 pselect6(16, [3 4 5 6 8 11 13 15], [], NULL, {0, 47323707}, {NULL, 8}) = 0 (Timeout) <0.047388>
00:04:34.557354 pselect6(16, [3 4 5 6 8 11 13 15], [], NULL, {0, 15370771}, {NULL, 8}) = 0 (Timeout) <0.015441>
00:04:34.572965 pselect6(16, [3 4 5 6 8 11 13 15], [], NULL, {0, 41203200}, {NULL, 8}) = 0 (Timeout) <0.041293>
00:04:34.614484 pselect6(16, [3 4 5 6 8 11 13 15], [], NULL, {0, 308212924}, {NULL, 8}) = 0 (Timeout) <0.308560>
00:04:34.923287 pselect6(16, [3 4 5 6 8 11 13 15], [], NULL, {0, 585891448}, {NULL, 8}) = 1 (in [3], left {0, 578913641}) <0.006996>
00:04:34.930384 --- SIGIO (I/O possible) @ 0 (0) ---
00:04:34.930428 rt_sigreturn(0x1d)      = 1 <0.000011>
00:04:34.930476 ioctl(3, FIONREAD, [1]) = 0 <0.000009>
00:04:34.930530 read(3, "\30", 1)       = 1 <0.000011>
00:04:34.930580 ioctl(3, FIONREAD, [0]) = 0 <0.000008>
00:04:34.930618 ioctl(3, FIONREAD, [0]) = 0 <0.000007>
00:04:34.930823 ioctl(3, FIONREAD, [0]) = 0 <0.000010>
00:04:34.930874 pselect6(16, [3 4 5 6 8 11 13 15], [], NULL, {0, 499903433}, {NULL, 8}) = 1 (in [3], left {0, 139494667}) <0.360435>
00:04:35.291412 --- SIGIO (I/O possible) @ 0 (0) ---
00:04:35.291451 rt_sigreturn(0x1d)      = 1 <0.000023>
00:04:35.291514 ioctl(3, FIONREAD, [1]) = 0 <0.000012>
00:04:35.291627 read(3, "\5", 1)        = 1 <0.000011>
00:04:35.291673 ioctl(3, FIONREAD, [0]) = 0 <0.000009>
00:04:35.291711 ioctl(3, FIONREAD, [0]) = 0 <0.000008>

That was the C-x C-e to execute the code fragment.

00:04:35.292167 faccessat(AT_FDCWD, "/home/forcer/.", F_OK) = 0 <0.000017>
00:04:35.292258 faccessat(AT_FDCWD, "/home/forcer/.virtualenvs/elpy/bin/bash", X_OK) = -1 ENOENT (No such file or directory) <0.000021>
00:04:35.292340 faccessat(AT_FDCWD, "/home/forcer/bin/bash", X_OK) = -1 ENOENT (No such file or directory) <0.000012>
00:04:35.292397 faccessat(AT_FDCWD, "/home/forcer/bin/bash", X_OK) = -1 ENOENT (No such file or directory) <0.000011>
00:04:35.292450 faccessat(AT_FDCWD, "/usr/local/bin/bash", X_OK) = -1 ENOENT (No such file or directory) <0.000014>
00:04:35.292506 faccessat(AT_FDCWD, "/usr/bin/bash", X_OK) = -1 ENOENT (No such file or directory) <0.000012>
00:04:35.292571 faccessat(AT_FDCWD, "/bin/bash", X_OK) = 0 <0.000012>
00:04:35.292614 stat("/bin/bash", {st_mode=S_IFREG|0755, st_size=975488, ...}) = 0 <0.000011>
00:04:35.292700 open("/dev/ptmx", O_RDWR|O_NOCTTY|O_CLOEXEC) = 9 <0.000080>
00:04:35.292816 fcntl(9, F_SETFD, FD_CLOEXEC) = 0 <0.000009>
00:04:35.292867 rt_sigprocmask(SIG_BLOCK, [CHLD], NULL, 8) = 0 <0.000009>
00:04:35.292914 ioctl(9, SNDCTL_TMR_TIMEBASE or TCGETS, {B38400 opost isig icanon echo ...}) = 0 <0.000009>
00:04:35.292956 ioctl(9, TIOCGPTN, [3]) = 0 <0.000008>
00:04:35.292992 stat("/dev/pts/3", {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 3), ...}) = 0 <0.000012>
00:04:35.293053 getuid()                = 1000 <0.000008>
00:04:35.293088 ioctl(9, TIOCSPTLCK, [0]) = 0 <0.000007>
00:04:35.293136 ioctl(9, SNDCTL_TMR_TIMEBASE or TCGETS, {B38400 opost isig icanon echo ...}) = 0 <0.000009>
00:04:35.293183 ioctl(9, TIOCGPTN, [3]) = 0 <0.000011>
00:04:35.293234 stat("/dev/pts/3", {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 3), ...}) = 0 <0.000010>
00:04:35.293298 rt_sigprocmask(SIG_UNBLOCK, [CHLD], NULL, 8) = 0 <0.000008>
00:04:35.293340 faccessat(AT_FDCWD, "/dev/pts/3", R_OK|W_OK) = 0 <0.000012>
00:04:35.293382 ioctl(9, FIONBIO, [1])  = 0 <0.000008>
00:04:35.293420 pipe2([16, 17], O_CLOEXEC) = 0 <0.000017>
00:04:35.293471 fcntl(9, F_SETFL, O_RDONLY|O_NONBLOCK) = 0 <0.000008>
00:04:35.293507 fcntl(9, F_SETFL, O_RDONLY|O_NONBLOCK) = 0 <0.000007>
00:04:35.293544 rt_sigprocmask(SIG_BLOCK, [INT CHLD], [], 8) = 0 <0.000008>
00:04:35.293586 vfork()                 = 19552 <0.000219>
00:04:35.293841 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0 <0.000009>
00:04:35.293884 close(17)               = 0 <0.000010>
00:04:35.293922 read(16, "", 1)         = 0 <0.000027>
00:04:35.293979 close(16)               = 0 <0.000015>

Here, the process output is read:

00:04:35.294032 pselect6(16, [4 5 6 8 9 11 13 15], [], NULL, {0, 215142592}, {NULL, 8}) = 1 (in [9], left {0, 212580423}) <0.002577>
00:04:35.296688 read(9, "foo\n", 4096)  = 4 <0.000013>
00:04:35.296775 pselect6(16, [4 5 6 8 11 13 15], [], NULL, {0, 20000000}, {NULL, 8}) = 0 (Timeout) <0.020087>

So far, so good. But now Emacs waits for the two seconds, even though
input was available.

00:04:35.316940 pselect6(16, [4 5 6 8 9 11 13 15], [], NULL, {0, 192233874}, {NULL, 8}) = 0 (Timeout) <0.192464>
00:04:35.509574 pselect6(16, [4 5 6 8 9 11 13 15], [], NULL, {0, 999602693}, {NULL, 8}) = ? ERESTARTNOHAND (To be restarted) <0.165729>

This is me hitting "cursor up" to see when it stops hanging.

00:04:35.675387 --- SIGIO (I/O possible) @ 0 (0) ---
00:04:35.675431 rt_sigreturn(0x1d)      = -1 EINTR (Interrupted system call) <0.000016>
00:04:35.675495 ioctl(3, FIONREAD, [3]) = 0 <0.000015>
00:04:35.675558 read(3, "\33OA", 3)     = 3 <0.000017>
00:04:35.675621 ioctl(3, FIONREAD, [0]) = 0 <0.000013>
00:04:35.675676 ioctl(3, FIONREAD, [0]) = 0 <0.000013>
00:04:35.675845 pselect6(16, [4 5 6 8 9 11 13 15], [], NULL, {0, 881234617}, {NULL, 8}) = 0 (Timeout) <0.882159>
00:04:36.558240 pselect6(16, [4 5 6 8 9 11 13 15], [], NULL, {0, 55923632}, {NULL, 8}) = 0 (Timeout) <0.056018>
00:04:36.614482 pselect6(16, [4 5 6 8 9 11 13 15], [], NULL, {0, 679593160}, {NULL, 8}) = 0 (Timeout) <0.680313>

Two seconds up. Buffer is destroyed, so the child is killed. The rest
isn't too interesting.

00:04:37.294951 rt_sigprocmask(SIG_BLOCK, [INT CHLD], [], 8) = 0 <0.000009>
00:04:37.295010 kill(4294947744, SIGHUP) = 0 <0.000191>
00:04:37.295232 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0 <0.000010>
00:04:37.295278 --- SIGCHLD (Child exited) @ 0 (0) ---
00:04:37.295308 wait4(19552, [{WIFSIGNALED(s) && WTERMSIG(s) == SIGHUP}], WNOHANG|WSTOPPED|WCONTINUED, NULL) = 19552 <0.000018>
00:04:37.295359 wait4(14261, 0x7fff19905b2c, WNOHANG|WSTOPPED|WCONTINUED, NULL) = 0 <0.000009>
00:04:37.295393 wait4(11218, 0x7fff19905b2c, WNOHANG|WSTOPPED|WCONTINUED, NULL) = 0 <0.000009>
00:04:37.295426 wait4(7041, 0x7fff19905b2c, WNOHANG|WSTOPPED|WCONTINUED, NULL) = 0 <0.000009>
00:04:37.295460 wait4(7035, 0x7fff19905b2c, WNOHANG|WSTOPPED|WCONTINUED, NULL) = 0 <0.000008>
00:04:37.295491 rt_sigreturn(0x11)      = 0 <0.000009>
00:04:37.296854 rt_sigprocmask(SIG_BLOCK, [WINCH IO], NULL, 8) = 0 <0.000011>
00:04:37.297034 write(3, "\33[50;1H\33[?25lt\33[4;1H\33[34h\33[?25h\33"..., 36) = 36 <0.000016>
00:04:37.297093 rt_sigprocmask(SIG_UNBLOCK, [WINCH IO], NULL, 8) = 0 <0.000009>
00:04:37.297375 --- SIGIO (I/O possible) @ 0 (0) ---
00:04:37.297398 rt_sigreturn(0x1d)      = 5 <0.000010>
00:04:37.297469 rt_sigprocmask(SIG_BLOCK, [WINCH IO], NULL, 8) = 0 <0.000009>
00:04:37.297564 ioctl(3, FIONREAD, [0]) = 0 <0.000011>
00:04:37.297609 rt_sigprocmask(SIG_UNBLOCK, [WINCH IO], NULL, 8) = 0 <0.000009>
00:04:37.297713 rt_sigprocmask(SIG_BLOCK, [WINCH IO], NULL, 8) = 0 <0.000009>
00:04:37.297813 write(3, "\33[50;1H\33[K\33[4;1H", 16) = 16 <0.000011>
00:04:37.297858 rt_sigprocmask(SIG_UNBLOCK, [WINCH IO], NULL, 8) = 0 <0.000007>
00:04:37.298406 --- SIGIO (I/O possible) @ 0 (0) ---
00:04:37.298429 rt_sigreturn(0x1d)      = 17450765 <0.000010>
00:04:37.298476 ioctl(3, FIONREAD, [0]) = 0 <0.000009>
00:04:37.298879 rt_sigprocmask(SIG_BLOCK, [WINCH IO], NULL, 8) = 0 <0.000009>
00:04:37.298987 write(3, "\33[9;35H\33[?25l\33[3m7\33[0m\33[39;49m\33["..., 56) = 56 <0.000011>
00:04:37.299035 rt_sigprocmask(SIG_UNBLOCK, [WINCH IO], NULL, 8) = 0 <0.000008>
00:04:37.299108 ioctl(3, FIONREAD, [0]) = 0 <0.000009>
00:04:37.299163 pselect6(16, [3 4 5 6 8 11 13 15], NULL, NULL, {0, 0}, {NULL, 8}) = 0 (Timeout) <0.000013>
00:04:37.299213 read(9, 0x7fff19905540, 4096) = -1 EAGAIN (Resource temporarily unavailable) <0.000009>
00:04:37.299362 --- SIGIO (I/O possible) @ 0 (0) ---
00:04:37.299384 rt_sigreturn(0x1d)      = 58958800 <0.000009>
00:04:37.299439 close(9)                = 0 <0.000027>
00:04:37.299498 ioctl(3, FIONREAD, [0]) = 0 <0.000009>
00:04:37.300337 rt_sigprocmask(SIG_BLOCK, [WINCH IO], NULL, 8) = 0 <0.000010>
00:04:37.300474 rt_sigprocmask(SIG_UNBLOCK, [WINCH IO], NULL, 8) = 0 <0.000009>
00:04:37.300556 ioctl(3, FIONREAD, [0]) = 0 <0.000009>
00:04:37.300600 pselect6(16, [3 4 5 6 8 11 13 15], [], NULL, {0, 208572483}, {NULL, 8}) = 0 (Timeout) <0.208822>
00:04:37.509648 pselect6(16, [3 4 5 6 8 11 13 15], [], NULL, {0, 47428499}, {NULL, 8}) = 0 (Timeout) <0.047519>
00:04:37.557429 pselect6(16, [3 4 5 6 8 11 13 15], [], NULL, {0, 15296896}, {NULL, 8}) = 0 (Timeout) <0.015382>
00:04:37.573017 pselect6(16, [3 4 5 6 8 11 13 15], [], NULL, {0, 41145931}, {NULL, 8}) = 0 (Timeout) <0.041237>
00:04:37.614468 pselect6(16, [3 4 5 6 8 11 13 15], [], NULL, {0, 184612087}, {NULL, 8}) = 0 (Timeout) <0.184836>
00:04:37.800025 pselect6(16, [3 4 5 6 8 11 13 15], [], NULL, {0, 122673194}, {NULL, 8}) = 0 (Timeout) <0.122837>
00:04:37.923084 pselect6(16, [3 4 5 6 8 11 13 15], [], NULL, {0, 586093728}, {NULL, 8} <unfinished ...>


Now, to a different Emacs, where it returns immediately:

00:05:21.788956 pselect6(4, [3], [], NULL, {99712, 668876746}, {NULL, 8}) = 1 (in [3], left {99711, 566613909}) <1.102290>
00:05:22.891441 --- SIGIO (I/O possible) @ 0 (0) ---
00:05:22.891493 rt_sigreturn(0x1d)      = 1 <0.000010>
00:05:22.891545 ioctl(3, FIONREAD, [1]) = 0 <0.000010>
00:05:22.891601 read(3, "\30", 1)       = 1 <0.000011>
00:05:22.891653 ioctl(3, FIONREAD, [0]) = 0 <0.000008>
00:05:22.891693 ioctl(3, FIONREAD, [0]) = 0 <0.000009>
00:05:22.891895 rt_sigprocmask(SIG_BLOCK, [WINCH IO], NULL, 8) = 0 <0.000010>
00:05:22.892066 write(3, "\33[50;1H\33[K\33[11;1H", 17) = 17 <0.000013>
00:05:22.892122 rt_sigprocmask(SIG_UNBLOCK, [WINCH IO], NULL, 8) = 0 <0.000008>
00:05:22.892182 ioctl(3, FIONREAD, [0]) = 0 <0.000011>
00:05:22.892232 pselect6(4, [3], [], NULL, {0, 499940522}, {NULL, 8}) = ? ERESTARTNOHAND (To be restarted) <0.000099>
00:05:22.892370 --- SIGIO (I/O possible) @ 0 (0) ---
00:05:22.892391 rt_sigreturn(0x1d)      = -1 EINTR (Interrupted system call) <0.000010>
00:05:22.892439 ioctl(3, FIONREAD, [0]) = 0 <0.000009>
00:05:22.892484 pselect6(4, [3], [], NULL, {0, 499686972}, {NULL, 8}) = 1 (in [3], left {0, 131907968}) <0.367804>
00:05:23.260373 --- SIGIO (I/O possible) @ 0 (0) ---
00:05:23.260424 rt_sigreturn(0x1d)      = 1 <0.000020>
00:05:23.260839 ioctl(3, FIONREAD, [1]) = 0 <0.000009>
00:05:23.260882 read(3, "\5", 1)        = 1 <0.000009>
00:05:23.260931 ioctl(3, FIONREAD, [0]) = 0 <0.000017>
00:05:23.260997 ioctl(3, FIONREAD, [0]) = 0 <0.000007>

Again, the C-x C-e above.

00:05:23.261331 faccessat(AT_FDCWD, "/home/forcer/.", F_OK) = 0 <0.000015>
00:05:23.261406 faccessat(AT_FDCWD, "/home/forcer/bin/bash", X_OK) = -1 ENOENT (No such file or directory) <0.000011>
00:05:23.261460 faccessat(AT_FDCWD, "/home/forcer/bin/bash", X_OK) = -1 ENOENT (No such file or directory) <0.000009>
00:05:23.261504 faccessat(AT_FDCWD, "/usr/local/bin/bash", X_OK) = -1 ENOENT (No such file or directory) <0.000011>
00:05:23.261550 faccessat(AT_FDCWD, "/usr/bin/bash", X_OK) = -1 ENOENT (No such file or directory) <0.000011>
00:05:23.261604 faccessat(AT_FDCWD, "/bin/bash", X_OK) = 0 <0.000010>
00:05:23.261640 stat("/bin/bash", {st_mode=S_IFREG|0755, st_size=975488, ...}) = 0 <0.000008>
00:05:23.261709 open("/dev/ptmx", O_RDWR|O_NOCTTY|O_CLOEXEC) = 4 <0.000047>
00:05:23.261787 fcntl(4, F_SETFD, FD_CLOEXEC) = 0 <0.000007>
00:05:23.261818 rt_sigprocmask(SIG_BLOCK, [CHLD], NULL, 8) = 0 <0.000006>
00:05:23.261852 ioctl(4, SNDCTL_TMR_TIMEBASE or TCGETS, {B38400 opost isig icanon echo ...}) = 0 <0.000008>
00:05:23.261887 ioctl(4, TIOCGPTN, [3]) = 0 <0.000006>
00:05:23.261917 stat("/dev/pts/3", {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 3), ...}) = 0 <0.000011>
00:05:23.261966 getuid()                = 1000 <0.000006>
00:05:23.261994 ioctl(4, TIOCSPTLCK, [0]) = 0 <0.000006>
00:05:23.262023 ioctl(4, SNDCTL_TMR_TIMEBASE or TCGETS, {B38400 opost isig icanon echo ...}) = 0 <0.000007>
00:05:23.262055 ioctl(4, TIOCGPTN, [3]) = 0 <0.000007>
00:05:23.262084 stat("/dev/pts/3", {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 3), ...}) = 0 <0.000008>
00:05:23.262130 rt_sigprocmask(SIG_UNBLOCK, [CHLD], NULL, 8) = 0 <0.000011>
00:05:23.262174 faccessat(AT_FDCWD, "/dev/pts/3", R_OK|W_OK) = 0 <0.000011>
00:05:23.262211 ioctl(4, FIONBIO, [1])  = 0 <0.000006>
00:05:23.262243 pipe2([5, 6], O_CLOEXEC) = 0 <0.000017>
00:05:23.262290 fcntl(4, F_SETFL, O_RDONLY|O_NONBLOCK) = 0 <0.000007>
00:05:23.262319 fcntl(4, F_SETFL, O_RDONLY|O_NONBLOCK) = 0 <0.000007>
00:05:23.262348 rt_sigprocmask(SIG_BLOCK, [INT CHLD], [], 8) = 0 <0.000007>
00:05:23.262383 vfork()                 = 19579 <0.000176>
00:05:23.262587 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0 <0.000008>
00:05:23.262621 close(6)                = 0 <0.000007>
00:05:23.262652 read(5, "", 1)          = 0 <0.000019>
00:05:23.262711 close(5)                = 0 <0.000014>

Now, Emacs reads the output, just as above:

00:05:23.262767 pselect6(5, [4], [], NULL, {1, 999999432}, {NULL, 8}) = 1 (in [4], left {1, 997510494}) <0.002500>
00:05:23.265315 read(4, "foo\n", 4096)  = 4 <0.000010>
00:05:23.265375 pselect6(5, [], [], NULL, {0, 20000000}, {NULL, 8}) = 0 (Timeout) <0.020067>

The first pselect after the close() call now has a 2s delay as per the
accept-process-output call. Above, that pselect had a much shorter
delay. And here, Emacs does not go back to waiting another 2s, but just
destroys the buffer. Again, the rest isn't too interesting.

00:05:23.285512 rt_sigprocmask(SIG_BLOCK, [INT CHLD], [], 8) = 0 <0.000009>
00:05:23.285569 kill(4294947717, SIGHUP) = 0 <0.000130>
00:05:23.285728 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0 <0.000009>
00:05:23.285762 --- SIGCHLD (Child exited) @ 0 (0) ---
00:05:23.285785 wait4(19579, [{WIFSIGNALED(s) && WTERMSIG(s) == SIGHUP}], WNOHANG|WSTOPPED|WCONTINUED, NULL) = 19579 <0.000015>
00:05:23.285830 rt_sigreturn(0x11)      = 0 <0.000009>
00:05:23.286237 rt_sigprocmask(SIG_BLOCK, [WINCH IO], NULL, 8) = 0 <0.000016>
00:05:23.286418 write(3, "\33[50;1H\33[?25lt\33[11;1H\33[34h\33[?25h"..., 37) = 37 <0.000013>
00:05:23.286477 rt_sigprocmask(SIG_UNBLOCK, [WINCH IO], NULL, 8) = 0 <0.000008>
00:05:23.286525 ioctl(3, FIONREAD, [0]) = 0 <0.000009>
00:05:23.286585 pselect6(5, [3], NULL, NULL, {0, 0}, {NULL, 8}) = 0 (Timeout) <0.000010>
00:05:23.286626 read(4, 0x7fffe6202c90, 4096) = -1 EAGAIN (Resource temporarily unavailable) <0.000009>
00:05:23.286686 close(4)                = 0 <0.000019>
00:05:23.286949 rt_sigprocmask(SIG_BLOCK, [WINCH IO], NULL, 8) = 0 <0.000010>
00:05:23.287081 rt_sigprocmask(SIG_UNBLOCK, [WINCH IO], NULL, 8) = 0 <0.000009>
00:05:23.287169 rt_sigprocmask(SIG_BLOCK, [WINCH IO], NULL, 8) = 0 <0.000009>
00:05:23.287276 rt_sigprocmask(SIG_UNBLOCK, [WINCH IO], NULL, 8) = 0 <0.000012>
00:05:23.287332 ioctl(3, FIONREAD, [0]) = 0 <0.000009>
00:05:23.287372 pselect6(4, [3], [], NULL, {0, 499144117}, {NULL, 8}) = ? ERESTARTNOHAND (To be restarted) <0.000134>
00:05:23.287537 --- SIGIO (I/O possible) @ 0 (0) ---
00:05:23.287556 rt_sigreturn(0x1d)      = -1 EINTR (Interrupted system call) <0.000009>
00:05:23.287593 ioctl(3, FIONREAD, [0]) = 0 <0.000008>
00:05:23.287631 pselect6(4, [3], [], NULL, {0, 498884056}, {NULL, 8}) = 0 (Timeout) <0.499429>
00:05:23.787255 rt_sigprocmask(SIG_BLOCK, [WINCH IO], NULL, 8) = 0 <0.000010>
00:05:23.787413 rt_sigprocmask(SIG_UNBLOCK, [WINCH IO], NULL, 8) = 0 <0.000009>
00:05:23.787462 pselect6(4, [3], [], NULL, {29, 499910845}, {NULL, 8}) = 1 (in [3], left {28, 748227541}) <0.751721>
00:05:24.539262 --- SIGIO (I/O possible) @ 0 (0) ---
00:05:24.539300 rt_sigreturn(0x1d)      = 1 <0.000011>
00:05:24.539345 ioctl(3, FIONREAD, [3]) = 0 <0.000009>
00:05:24.539384 read(3, "\33OA", 3)     = 3 <0.000010>
00:05:24.539422 ioctl(3, FIONREAD, [0]) = 0 <0.000009>
00:05:24.539456 ioctl(3, FIONREAD, [0]) = 0 <0.000008>
00:05:24.540507 rt_sigprocmask(SIG_BLOCK, [WINCH IO], NULL, 8) = 0 <0.000011>
00:05:24.540670 write(3, "\33[50;1H\33[K\33[49;34H\33[?25l\33[3m9 \33["..., 70) = 70 <0.000013>
00:05:24.540722 rt_sigprocmask(SIG_UNBLOCK, [WINCH IO], NULL, 8) = 0 <0.000008>
00:05:24.540768 ioctl(3, FIONREAD, [0]) = 0 <0.000009>
00:05:24.540809 pselect6(4, [3], [], NULL, {0, 499953398}, {NULL, 8}) = ? ERESTARTNOHAND (To be restarted) <0.000393>
00:05:24.541237 --- SIGIO (I/O possible) @ 0 (0) ---
00:05:24.541256 rt_sigreturn(0x1d)      = -1 EINTR (Interrupted system call) <0.000009>
00:05:24.541293 ioctl(3, FIONREAD, [0]) = 0 <0.000008>
00:05:24.541331 pselect6(4, [3], [], NULL, {0, 499431017}, {NULL, 8}) = 0 (Timeout) <0.499831>
00:05:25.041328 pselect6(4, [3], [], NULL, {29, 499485945}, {NULL, 8} <unfinished ...>

Regards,
Jorgen




Information forwarded to bug-gnu-emacs <at> gnu.org:
bug#17647; Package emacs. (Mon, 02 Jun 2014 23:23:01 GMT) Full text and rfc822 format available.

Message #8 received at 17647 <at> debbugs.gnu.org (full text, mbox):

From: Paul Eggert <eggert <at> cs.ucla.edu>
To: Jorgen Schaefer <forcer <at> forcix.cx>
Cc: 17647 <at> debbugs.gnu.org
Subject: Re: 24.4.50; accept-process-output with process nil can miss output
Date: Mon, 02 Jun 2014 16:21:56 -0700
Are you using gnutls?

What does M-x list-processes say, in a buggy Emacs?




Information forwarded to bug-gnu-emacs <at> gnu.org:
bug#17647; Package emacs. (Tue, 03 Jun 2014 19:47:01 GMT) Full text and rfc822 format available.

Message #11 received at 17647 <at> debbugs.gnu.org (full text, mbox):

From: Jorgen Schaefer <forcer <at> forcix.cx>
To: Paul Eggert <eggert <at> cs.ucla.edu>
Cc: 17647 <at> debbugs.gnu.org
Subject: Re: 24.4.50; accept-process-output with process nil can miss output
Date: Tue, 3 Jun 2014 21:46:10 +0200
On Mon, 02 Jun 2014 16:21:56 -0700
Paul Eggert <eggert <at> cs.ucla.edu> wrote:

> Are you using gnutls?

Not that I know. ldd `which emacs` does not list any gnutls links.

> What does M-x list-processes say, in a buggy Emacs?

As this blocks input, I can't actually run M-x list-processes while
reproducing the problem. Running list-processes right after
set-process-query-on-exit and before accept-process-output in my
example says:

test            run      *temp*-447149  /dev/pts/5   bash -c echo foo ; sleep 5



I should add that process filters are called at the start of
`accept-process-output', but it still hangs. This is different from
what I thought was the case initially, but that was a debugging mistake
due to output not being updated until after `accept-process-output'
returns.

That is, with time stamps:

(with-temp-buffer
  (let ((proc (start-process "test" (current-buffer) "bash" "-c"
                             "echo foo ; sleep 5")))
    (set-process-query-on-exit-flag proc nil)
    (set-process-filter proc (lambda (proc str)
                               (message "Filter: %s" (float-time))))
    (message "Before: %s" (float-time))
    (accept-process-output nil 2) 
    (message "After.: %s" (float-time))))

Before: 1401824504.1458359
Filter: 1401824504.148198
After.: 1401824506.146296

Regards,
Jorgen




Information forwarded to bug-gnu-emacs <at> gnu.org:
bug#17647; Package emacs. (Tue, 10 Jun 2014 03:41:01 GMT) Full text and rfc822 format available.

Message #14 received at 17647 <at> debbugs.gnu.org (full text, mbox):

From: Paul Eggert <eggert <at> cs.ucla.edu>
To: Jorgen Schaefer <forcer <at> forcix.cx>
Cc: 17647 <at> debbugs.gnu.org
Subject: Re: 24.4.50; accept-process-output with process nil can miss output
Date: Mon, 09 Jun 2014 20:40:12 -0700
[Message part 1 (text/plain, inline)]
I took a look at the nearby code and found some glitches that I can fix. 
 Could you please try the attached patch (relative to trunk bzr 
117299) and see whether it helps you, or at least does not hurt you? 
Thanks.
[apo.patch (text/plain, attachment)]

Information forwarded to bug-gnu-emacs <at> gnu.org:
bug#17647; Package emacs. (Fri, 13 Jun 2014 15:49:02 GMT) Full text and rfc822 format available.

Message #17 received at 17647 <at> debbugs.gnu.org (full text, mbox):

From: Jorgen Schaefer <forcer <at> forcix.cx>
To: Paul Eggert <eggert <at> cs.ucla.edu>
Cc: 17647 <at> debbugs.gnu.org
Subject: Re: 24.4.50; accept-process-output with process nil can miss output
Date: Fri, 13 Jun 2014 17:48:39 +0200
On Mon, 09 Jun 2014 20:40:12 -0700
Paul Eggert <eggert <at> cs.ucla.edu> wrote:

> I took a look at the nearby code and found some glitches that I can
> fix. Could you please try the attached patch (relative to trunk bzr 
> 117299) and see whether it helps you, or at least does not hurt you? 
> Thanks.

I've been running the patched version for three days now. No problems,
and the bug did not reoccur. It seems you caught it.

Thank you!

Jorgen




Reply sent to Paul Eggert <eggert <at> cs.ucla.edu>:
You have taken responsibility. (Fri, 13 Jun 2014 15:56:02 GMT) Full text and rfc822 format available.

Notification sent to Jorgen Schaefer <forcer <at> forcix.cx>:
bug acknowledged by developer. (Fri, 13 Jun 2014 15:56:02 GMT) Full text and rfc822 format available.

Message #22 received at 17647-done <at> debbugs.gnu.org (full text, mbox):

From: Paul Eggert <eggert <at> cs.ucla.edu>
To: Jorgen Schaefer <forcer <at> forcix.cx>
Cc: 17647-done <at> debbugs.gnu.org
Subject: Re: 24.4.50; accept-process-output with process nil can miss output
Date: Fri, 13 Jun 2014 08:55:25 -0700
Thanks for checking it.  I installed that fix into the trunk.




Information forwarded to bug-gnu-emacs <at> gnu.org:
bug#17647; Package emacs. (Wed, 25 Jun 2014 19:16:02 GMT) Full text and rfc822 format available.

Message #25 received at 17647 <at> debbugs.gnu.org (full text, mbox):

From: Glenn Morris <rgm <at> gnu.org>
To: 17647 <at> debbugs.gnu.org
Cc: eggert <at> cs.ucla.edu, forcer <at> forcix.cx
Subject: Re: bug#17647: 24.4.50;
 accept-process-output with process nil can miss output
Date: Wed, 25 Jun 2014 15:14:58 -0400
It's possible this change did... something.

If I run `make check' in the "current" (before 117400) trunk, I get:

2 unexpected results:
   FAILED  warning-predicate-function-gcc
   FAILED  warning-predicate-rx-gcc

You can see the same failures on hydra.
They seem to start at

http://hydra.nixos.org/build/11864228

which corresponds to

http://lists.gnu.org/archive/html/emacs-diffs/2014-06/msg00165.html


We did not notice these failures because for some reason Emacs still
exits with status 0, despite (kill-emacs 1) being called in
ert-run-tests-batch-and-exit (???).


To reproduce the issue, do (prior to my latest change to flymake-tests.el):

cd test/automated
../../src/emacs -Q -batch -l ./flymake-tests.el \
   -f ert-run-tests-batch-and-exit < /dev/null

It returns far too quickly, as if it did not sleep at all.
I found that (sleep-for 1.0) did nothing, but 
(sleep-for 0.5) (sleep-for 0.5) worked.


Frankly I have no idea what is going on, with the sleeping nor with the
(kill-emacs 1). But it seems to have something to do with processes, and
your change is related to processes, so... over to you! ;)




Information forwarded to bug-gnu-emacs <at> gnu.org:
bug#17647; Package emacs. (Wed, 25 Jun 2014 22:44:01 GMT) Full text and rfc822 format available.

Message #28 received at 17647 <at> debbugs.gnu.org (full text, mbox):

From: Glenn Morris <rgm <at> gnu.org>
To: 17647 <at> debbugs.gnu.org
Cc: eggert <at> cs.ucla.edu, forcer <at> forcix.cx
Subject: Re: bug#17647: 24.4.50;
 accept-process-output with process nil can miss output
Date: Wed, 25 Jun 2014 18:43:23 -0400
Glenn Morris wrote:

> It returns far too quickly, as if it did not sleep at all.
> I found that (sleep-for 1.0) did nothing, but 
> (sleep-for 0.5) (sleep-for 0.5) worked.

This is http://debbugs.gnu.org/15990, so probably unrelated to recent changes.

> Frankly I have no idea what is going on,

I felt like repeating that...




bug archived. Request was from Debbugs Internal Request <help-debbugs <at> gnu.org> to internal_control <at> debbugs.gnu.org. (Thu, 24 Jul 2014 11:24:04 GMT) Full text and rfc822 format available.

This bug report was last modified 9 years and 250 days ago.

Previous Next


GNU bug tracking system
Copyright (C) 1999 Darren O. Benham, 1997,2003 nCipher Corporation Ltd, 1994-97 Ian Jackson.