From mboxrd@z Thu Jan 1 00:00:00 1970 Path: news.gmane.org!not-for-mail From: Jorgen Schaefer Newsgroups: gmane.emacs.bugs Subject: bug#17647: 24.4.50; accept-process-output with process nil can miss output Date: Sat, 31 May 2014 00:24:57 +0200 Message-ID: <87wqd229c6.fsf@loki.jorgenschaefer.de> NNTP-Posting-Host: plane.gmane.org Mime-Version: 1.0 Content-Type: text/plain X-Trace: ger.gmane.org 1401488793 3602 80.91.229.3 (30 May 2014 22:26:33 GMT) X-Complaints-To: usenet@ger.gmane.org NNTP-Posting-Date: Fri, 30 May 2014 22:26:33 +0000 (UTC) To: 17647@debbugs.gnu.org Original-X-From: bug-gnu-emacs-bounces+geb-bug-gnu-emacs=m.gmane.org@gnu.org Sat May 31 00:26:26 2014 Return-path: Envelope-to: geb-bug-gnu-emacs@m.gmane.org Original-Received: from lists.gnu.org ([208.118.235.17]) by plane.gmane.org with esmtp (Exim 4.69) (envelope-from ) id 1WqVFn-0003D1-Tm for geb-bug-gnu-emacs@m.gmane.org; Sat, 31 May 2014 00:26:24 +0200 Original-Received: from localhost ([::1]:56848 helo=lists.gnu.org) by lists.gnu.org with esmtp (Exim 4.71) (envelope-from ) id 1WqVFn-00062J-DR for geb-bug-gnu-emacs@m.gmane.org; Fri, 30 May 2014 18:26:23 -0400 Original-Received: from eggs.gnu.org ([2001:4830:134:3::10]:46876) by lists.gnu.org with esmtp (Exim 4.71) (envelope-from ) id 1WqVFb-0005pr-Ak for bug-gnu-emacs@gnu.org; Fri, 30 May 2014 18:26:20 -0400 Original-Received: from Debian-exim by eggs.gnu.org with spam-scanned (Exim 4.71) (envelope-from ) id 1WqVFS-0002Qs-7k for bug-gnu-emacs@gnu.org; Fri, 30 May 2014 18:26:11 -0400 Original-Received: from debbugs.gnu.org ([140.186.70.43]:39247) by eggs.gnu.org with esmtp (Exim 4.71) (envelope-from ) id 1WqVFS-0002Qo-4I for bug-gnu-emacs@gnu.org; Fri, 30 May 2014 18:26:02 -0400 Original-Received: from Debian-debbugs by debbugs.gnu.org with local (Exim 4.80) (envelope-from ) id 1WqVFR-0005hh-O9 for bug-gnu-emacs@gnu.org; Fri, 30 May 2014 18:26:01 -0400 X-Loop: help-debbugs@gnu.org Resent-From: Jorgen Schaefer Original-Sender: "Debbugs-submit" Resent-CC: bug-gnu-emacs@gnu.org Resent-Date: Fri, 30 May 2014 22:26:01 +0000 Resent-Message-ID: Resent-Sender: help-debbugs@gnu.org X-GNU-PR-Message: report 17647 X-GNU-PR-Package: emacs X-GNU-PR-Keywords: X-Debbugs-Original-To: bug-gnu-emacs@gnu.org Original-Received: via spool by submit@debbugs.gnu.org id=B.140148873321883 (code B ref -1); Fri, 30 May 2014 22:26:01 +0000 Original-Received: (at submit) by debbugs.gnu.org; 30 May 2014 22:25:33 +0000 Original-Received: from localhost ([127.0.0.1]:38124 helo=debbugs.gnu.org) by debbugs.gnu.org with esmtp (Exim 4.80) (envelope-from ) id 1WqVEw-0005gl-K3 for submit@debbugs.gnu.org; Fri, 30 May 2014 18:25:32 -0400 Original-Received: from eggs.gnu.org ([208.118.235.92]:45054) by debbugs.gnu.org with esmtp (Exim 4.80) (envelope-from ) id 1WqVEs-0005gQ-U4 for submit@debbugs.gnu.org; Fri, 30 May 2014 18:25:28 -0400 Original-Received: from Debian-exim by eggs.gnu.org with spam-scanned (Exim 4.71) (envelope-from ) id 1WqVEe-0002Kp-G2 for submit@debbugs.gnu.org; Fri, 30 May 2014 18:25:21 -0400 Original-Received: from lists.gnu.org ([2001:4830:134:3::11]:47325) by eggs.gnu.org with esmtp (Exim 4.71) (envelope-from ) id 1WqVEe-0002Kj-Cl for submit@debbugs.gnu.org; Fri, 30 May 2014 18:25:12 -0400 Original-Received: from eggs.gnu.org ([2001:4830:134:3::10]:46734) by lists.gnu.org with esmtp (Exim 4.71) (envelope-from ) id 1WqVEX-00048x-Ri for bug-gnu-emacs@gnu.org; Fri, 30 May 2014 18:25:12 -0400 Original-Received: from Debian-exim by eggs.gnu.org with spam-scanned (Exim 4.71) (envelope-from ) id 1WqVER-00025r-Lv for bug-gnu-emacs@gnu.org; Fri, 30 May 2014 18:25:05 -0400 Original-Received: from loki.jorgenschaefer.de ([87.230.15.51]:39106) by eggs.gnu.org with esmtp (Exim 4.71) (envelope-from ) id 1WqVER-00025f-8P for bug-gnu-emacs@gnu.org; Fri, 30 May 2014 18:24:59 -0400 Original-Received: by loki.jorgenschaefer.de (Postfix, from userid 1000) id 6071920313F; Sat, 31 May 2014 00:24:57 +0200 (CEST) X-detected-operating-system: by eggs.gnu.org: GNU/Linux 3.x X-detected-operating-system: by eggs.gnu.org: Error: Malformed IPv6 address (bad octet value). X-BeenThere: debbugs-submit@debbugs.gnu.org X-Mailman-Version: 2.1.15 Precedence: list X-detected-operating-system: by eggs.gnu.org: GNU/Linux 3.x X-Received-From: 140.186.70.43 X-BeenThere: bug-gnu-emacs@gnu.org List-Id: "Bug reports for GNU Emacs, the Swiss army knife of text editors" List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Errors-To: bug-gnu-emacs-bounces+geb-bug-gnu-emacs=m.gmane.org@gnu.org Original-Sender: bug-gnu-emacs-bounces+geb-bug-gnu-emacs=m.gmane.org@gnu.org Xref: news.gmane.org gmane.emacs.bugs:89777 Archived-At: 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} 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} Regards, Jorgen