bug#15075: 24.3.50; Infinite loop when closing some connections

bug#15075: 24.3.50; Infinite loop when closing some connections

[Lars Magne Ingebrigtsen]

When reading (via tls) from pop3, Emacs hangs hard upon closing the
connection.

strace says:

[pid 18991] read(17, 0x7fff4c6ac3f0, 4096) = -1 EBADF (Bad file descriptor)
[pid 18991] read(17, 0x7fff4c6ac3f0, 4096) = -1 EBADF (Bad file descriptor)
[pid 18991] read(17, 0x7fff4c6ac3f0, 4096) = -1 EBADF (Bad file descriptor)
[pid 18991] read(17, 0x7fff4c6ac3f0, 4096) = -1 EBADF (Bad file descriptor)
[pid 18991] read(17, 0x7fff4c6ac3f0, 4096) = -1 EBADF (Bad file descriptor)
[pid 18991] read(17, 0x7fff4c6ac3f0, 4096) = -1 EBADF (Bad file descriptor)
[pid 18991] read(17, 0x7fff4c6ac3f0, 4096) = -1 EBADF (Bad file descriptor)
[pid 18991] read(17, 0x7fff4c6ac3f0, 4096) = -1 EBADF (Bad file descriptor)
[pid 18991] read(17, 0x7fff4c6ac3f0, 4096) = -1 EBADF (Bad file descriptor)

/proc shows that fd 17 no longer exists, so it's probably been closed by
Emacs, and we're then inflooping in a read on that socket, for some
reason,

The last checkin is:

fixes bug: http://debbugs.gnu.org/15035
committer: Paul Eggert <eggert@cs.ucla.edu>
branch nick: trunk
timestamp: Mon 2013-08-12 00:12:07 -0700
message:
  Fix some fd issues when running subprocesses.

So that seems like a likely candidate.  :-)

Here's the gdb backtrace:

#0  0x00007ffff2f4718d in read () from /lib/x86_64-linux-gnu/libpthread.so.0
#1  0x00000000004e5086 in read (__nbytes=4096, __buf=0x7fffffffa340, __fd=21) at /usr/include/x86_64-linux-gnu/bits/unistd.h:45
#2  emacs_read (fildes=fildes@entry=21, buf=0x7fffffffa340 "+OK Logging out, messages deleted.\r\n", nbyte=4096) at sysdep.c:2300
#3  0x0000000000577820 in read_process_output (proc=proc@entry=26878253, channel=21) at process.c:4980
#4  0x000000000057c548 in wait_reading_process_output (time_limit=<optimized out>, nsecs=-1, read_kbd=read_kbd@entry=0, 
    do_display=do_display@entry=false, wait_for_cell=11969090, wait_proc=0x19a2128, just_wait_proc=0) at process.c:4435
#5  0x000000000057d541 in Faccept_process_output (process=26878253, seconds=<optimized out>, millisec=<optimized out>, 
    just_this_one=<optimized out>) at process.c:3948
#6  0x000000000053fb44 in Ffuncall (nargs=<optimized out>, args=<optimized out>) at eval.c:2864
#7  0x0000000000573b7b in exec_byte_code (bytestr=-9, vector=140737488331584, maxdepth=4096, args_template=140737488337176, 
    nargs=4611686018662268928, args=0x400000003f000000) at bytecode.c:905
#8  0x000000000053f5f1 in funcall_lambda (fun=25388357, nargs=nargs@entry=1, arg_vector=arg_vector@entry=0x7fffffffbaa0) at eval.c:3087
#9  0x000000000053f953 in Ffuncall (nargs=2, args=0x7fffffffba98) at eval.c:2914
#10 0x0000000000573b7b in exec_byte_code (bytestr=-9, vector=140737488331584, maxdepth=4096, args_template=0, nargs=4611686018662268928, 
    args=0x400000003f000000) at bytecode.c:905




In GNU Emacs 24.3.50.8 (x86_64-unknown-linux-gnu, X toolkit, Xaw scroll bars)
 of 2013-08-12 on stories
Bzr revision: 113815 rgm@gnu.org-20130812101743-djba3ieqivg87pnd
Windowing system distributor `The X.Org Foundation', version 11.0.11204000
System Description:	Debian GNU/Linux 7.0 (wheezy)

Important settings:
  value of $LANG: en_US
  locale-coding-system: iso-latin-1-unix
  default enable-multibyte-characters: t

Major mode: Bzr-Log-View

Minor modes in effect:
  tooltip-mode: t
  mouse-wheel-mode: t
  file-name-shadow-mode: t
  global-font-lock-mode: t
  font-lock-mode: t
  blink-cursor-mode: t
  auto-composition-mode: t
  auto-encryption-mode: t
  auto-compression-mode: t
  buffer-read-only: t
  line-number-mode: t

Recent input:
C-x C-f s r <tab> e m <tab> / t r <tab> p <backspace> 
s r <tab> p r <tab> o <tab> c <tab> c <tab> <return> 
C-x v l <help-echo> M-x r e p o <tab> r <tab> b <tab> 
<return>

Recent messages:
For information about GNU Emacs and the GNU system, type C-h C-a.
Making completion list... [2 times]
Loading cc-langs...done
Making completion list...

Load-path shadows:
/home/larsi/src/clock.el/clock hides /home/larsi/lisp/clock
/home/larsi/src/cddb.el/expect hides /home/larsi/lisp/expect
/home/larsi/src/pvr.el/pvr hides /home/larsi/lisp/pvr
~/pgnus/contrib/vcard hides /home/larsi/lisp/vcard
/home/larsi/src/cddb.el/captitle hides /home/larsi/lisp/captitle
~/lisp/zenirc-2.112/src/zenirc-example hides /home/larsi/lisp/zenirc-example
~/pgnus/contrib/compface hides /home/larsi/src/emacs/trunk/lisp/gnus/compface

Features:
(shadow sort hashcash emacsbug message format-spec rfc822 mml mml-sec
mailabbrev gmm-utils mailheader sendmail mail-utils log-view easy-mmode
pcvs-util vc vc-dispatcher vc-bzr cc-langs cc-mode cc-fonts cc-guess
cc-menus cc-cmds cc-styles cc-align cc-engine cc-vars cc-defs help-mode
debug uniquify soap-client mm-decode mm-bodies mm-encode url-http tls
url-auth mail-parse rfc2231 rfc2047 rfc2045 ietf-drums url-gw url
url-proxy url-privacy url-expand url-methods url-history url-cookie
url-domsuf url-util url-parse auth-source eieio byte-opt bytecomp
byte-compile cconv eieio-core gnus-util mm-util mail-prsvr
password-cache url-vars mailcap warnings xml ido flyspell ispell
benchmark w3m browse-url doc-view dired image-mode easymenu timezone
w3m-hist w3m-fb w3m-ems wid-edit w3m-ccl ccl w3m-favicon w3m-image
w3m-proc w3m-util cl-macs gv add-log mail-extr jka-compr cl cl-loaddefs
cl-lib time-date tooltip ediff-hook vc-hooks lisp-float-type mwheel
x-win x-dnd tool-bar dnd fontset image regexp-opt fringe tabulated-list
newcomment lisp-mode prog-mode register page menu-bar rfn-eshadow timer
select scroll-bar mouse jit-lock font-lock syntax facemenu font-core
frame cham georgian utf-8-lang misc-lang vietnamese tibetan thai
tai-viet lao korean japanese hebrew greek romanian slovak czech european
ethiopic indian cyrillic chinese case-table epa-hook jka-cmpr-hook help
simple abbrev minibuffer nadvice loaddefs button faces cus-face macroexp
files text-properties overlay sha1 md5 base64 format env code-pages mule
custom widget hashtable-print-readable backquote make-network-process
gfilenotify dynamic-setting system-font-setting font-render-setting
x-toolkit x multi-tty emacs)

-- 
(domestic pets only, the antidote for overdose, milk.)
  No Gnus T-Shirt for sale: http://ingebrigtsen.no/no.php
  and http://lars.ingebrigtsen.no/2013/08/twenty-years-of-september.html

bug#15075: 24.3.50; Infinite loop when closing some connections

[Lars Magne Ingebrigtsen]

It happened again -- this time when sending and email via SMTP + TLS.

strace output:

[pid 19377] read(17, 0x7ffff03e9bb0, 4096) = -1 EBADF (Bad file descriptor)
[pid 19377] read(17, 0x7ffff03e9bb0, 4096) = -1 EBADF (Bad file descriptor)
[pid 19377] read(17, 0x7ffff03e9bb0, 4096) = -1 EBADF (Bad file descriptor)
[pid 19377] read(17, 0x7ffff03e9bb0, 4096) = -1 EBADF (Bad file descriptor)
[pid 19377] read(17, 0x7ffff03e9bb0, 4096) = -1 EBADF (Bad file descriptor)
[pid 19377] read(17, 0x7ffff03e9bb0, 4096) = -1 EBADF (Bad file descriptor)

fd 17 again?  That's an odd coincidence...

-- 
(domestic pets only, the antidote for overdose, milk.)
  No Gnus T-Shirt for sale: http://ingebrigtsen.no/no.php
  and http://lars.ingebrigtsen.no/2013/08/twenty-years-of-september.html

bug#15075: 24.3.50; Infinite loop when closing some connections

[Lars Magne Ingebrigtsen]

Lars Magne Ingebrigtsen <larsi@gnus.org> writes:

> fd 17 again?  That's an odd coincidence...

Yeah, just a coincidence.  Here's the next hang upon sending an email:

[pid 20227] read(20, 0x7fff7389a190, 4096) = -1 EBADF (Bad file descriptor)
[pid 20227] read(20, 0x7fff7389a190, 4096) = -1 EBADF (Bad file descriptor)
[pid 20227] read(20, 0x7fff7389a190, 4096) = -1 EBADF (Bad file descriptor)
[pid 20227] read(20, 0x7fff7389a190, 4096) = -1 EBADF (Bad file descriptor)
[pid 20227] read(20, 0x7fff7389a190, 4096) = -1 EBADF (Bad file descriptor)
[pid 20227] read(20, 0x7fff7389a190, 4096) = -1 EBADF (Bad file descriptor)


-- 
(domestic pets only, the antidote for overdose, milk.)
  No Gnus T-Shirt for sale: http://ingebrigtsen.no/no.php
  and http://lars.ingebrigtsen.no/2013/08/twenty-years-of-september.html

bug#15075: 24.3.50; Infinite loop when closing some connections

[Lars Magne Ingebrigtsen]

Here's another gdb backtrace from when it hangs.  Hm...  Ok, I should
probably re-compile it with -O2.  I'll do that and get another hang.

0  0x00007ffff2f4718d in read () from /lib/x86_64-linux-gnu/libpthread.so.0
#1  0x00000000004e5086 in read (__nbytes=4096, __buf=0x7fffffffb6d0, __fd=21) at /usr/include/x86_64-linux-gnu/bits/unistd.h:45
#2  emacs_read (fildes=fildes@entry=21, buf=0x7fffffffb6d0 "221 hermes.netfonds.no closing connection\r\n", nbyte=4096) at sysdep.c:2300
#3  0x0000000000577820 in read_process_output (proc=proc@entry=85871045, channel=21) at process.c:4980
#4  0x000000000057c548 in wait_reading_process_output (time_limit=<optimized out>, nsecs=-1, read_kbd=read_kbd@entry=0, 
    do_display=do_display@entry=false, wait_for_cell=11969090, wait_proc=0x51e49c0, just_wait_proc=0) at process.c:4435
#5  0x000000000057d541 in Faccept_process_output (process=85871045, seconds=<optimized out>, millisec=<optimized out>, 
    just_this_one=<optimized out>) at process.c:3948

-- 
(domestic pets only, the antidote for overdose, milk.)
  No Gnus T-Shirt for sale: http://ingebrigtsen.no/no.php
  and http://lars.ingebrigtsen.no/2013/08/twenty-years-of-september.html

bug#15075: 24.3.50; Infinite loop when closing some connections

[Lars Magne Ingebrigtsen]

Hey, that was fast.

This bug isn't reliably repeatable, so it may be timing-related or
something.  But here's an -O0 build:

0  0x00007ffff2f4718d in read () from /lib/x86_64-linux-gnu/libpthread.so.0
#1  0x0000000000536ea3 in emacs_read (fildes=21, buf=0x7fffffff8830 "221 hermes.netfonds.no closing connection\r\n", nbyte=4096)
    at sysdep.c:2300
#2  0x00000000005f88c5 in read_process_output (proc=71750957, channel=21) at process.c:4980
#3  0x00000000005f71c3 in wait_reading_process_output (time_limit=0, nsecs=-1, read_kbd=0, do_display=false, wait_for_cell=12567106, 
    wait_proc=0x446d528, just_wait_proc=0) at process.c:4435
#4  0x00000000005f5f7f in Faccept_process_output (process=71750957, seconds=12567106, millisec=12567106, just_this_one=12567106)
    at process.c:3948
#5  0x00000000005abeea in Ffuncall (nargs=2, args=0x7fffffff9da8) at eval.c:2864
#6  0x00000000005ebce6 in exec_byte_code (bytestr=70546449, vector=72148261, maxdepth=20, args_template=12567106, nargs=0, args=0x0)
    at bytecode.c:905
#7  0x00000000005eb185 in Fbyte_code (bytestr=70546449, vector=72148261, maxdepth=20) at bytecode.c:478
#8  0x00000000005aaa4a in eval_sub (form=72367398) at eval.c:2229
#9  0x00000000005a8722 in internal_catch (tag=16167106, func=0x5aa416 <eval_sub>, arg=72367398) at eval.c:1113
#10 0x00000000005ecad6 in exec_byte_code (bytestr=68666769, vector=72148485, maxdepth=20, args_template=12567106, nargs=0, args=0x0)
    at bytecode.c:1086
#11 0x00000000005ac857 in funcall_lambda (fun=72148573, nargs=1, arg_vector=0x44ce605) at eval.c:3087
#12 0x00000000005ac04c in Ffuncall (nargs=2, args=0x7fffffffa8f8) at eval.c:2902
#13 0x00000000005ebce6 in exec_byte_code (bytestr=75448801, vector=72146685, maxdepth=12, args_template=12567106, nargs=0, args=0x0)
    at bytecode.c:905
#14 0x00000000005eb185 in Fbyte_code (bytestr=75448801, vector=72146685, maxdepth=12) at bytecode.c:478
#15 0x00000000005aaa4a in eval_sub (form=72371078) at eval.c:2229
#16 0x00000000005a74ce in Fprogn (body=72369206) at eval.c:460
#17 0x00000000005a750c in unwind_body (body=72369206) at eval.c:474

-- 
(domestic pets only, the antidote for overdose, milk.)
  No Gnus T-Shirt for sale: http://ingebrigtsen.no/no.php
  and http://lars.ingebrigtsen.no/2013/08/twenty-years-of-september.html

bug#15075: 24.3.50; Infinite loop when closing some connections

[Lars Magne Ingebrigtsen]

With an -O0 build, it's almost completely repeatable.

Here's the accompanying Lisp backtrace.  So it seems like we're sending
via gnutls, we send the quit command to the SMTP server, it says "bye"
and closes the connection, and then the next (?) call to
`accept-process-output' infloops.

Lisp Backtrace:
"accept-process-output" (0xffff9db0)
"byte-code" (0xffffa1b0)
"smtpmail-read-response" (0xffffa900)
"byte-code" (0xffffacf0)
"smtpmail-via-smtp" (0xffffb420)
"smtpmail-send-it" (0xffffb910)
"message-smtpmail-send-it" (0xffffbdd0)
"message-multi-smtp-send-mail" (0xffffc2a0)
"gnus-agent-send-mail" (0xffffc770)
"message-send-mail" (0xffffcc70)
"message-send-via-mail" (0xffffd130)
"message-send" (0xffffd610)
"message-send-and-exit" (0xffffdb18)
"call-interactively" (0xffffde30)
"command-execute" (0xffffe318)


-- 
(domestic pets only, the antidote for overdose, milk.)
  No Gnus T-Shirt for sale: http://ingebrigtsen.no/no.php
  and http://lars.ingebrigtsen.no/2013/08/twenty-years-of-september.html

bug#15075: 24.3.50; Infinite loop when closing some connections

[Lars Magne Ingebrigtsen]

This is what's hanging.  If we get any other errors than EIO, EAGAIN or
EWOULDBLOCK, then we infloop here.  And we get EBADF, so this infloops.

	  /* Read data from the process, until we exhaust it.  */
	  while (wait_proc->infd >= 0)
	    {
	      int nread = read_process_output (proc, wait_proc->infd);

	      if (nread == 0)
		break;

	      if (nread > 0)
		got_some_input = read_some_bytes = 1;
	      else if (nread == -1 && (errno == EIO || errno == EAGAIN))
		break;
#ifdef EWOULDBLOCK
	      else if (nread == -1 && EWOULDBLOCK == errno)
		break;
#endif
	    }

I'm guessing that something is supposed to set wait_proc->infd something
smaller than zero somewhere if a serious error happens.

Yup:

(gdb) print wait_proc->open_fd
$12 = {-1, -1, -1, -1, -1, -1}
(gdb) print wait_proc->infd   
$13 = 21

And this looks like the likely culprit:

-      p->infd  = -1;
-      p->outfd = -1;
+  for (i = 0; i < PROCESS_OPEN_FDS; i++)
+    close_process_fd (&p->open_fd[i]);

So there's some disagreement about what's saying whether sockets are
open or not, and if the closing happens at the wrong time, we infloop.

-- 
(domestic pets only, the antidote for overdose, milk.)
  No Gnus T-Shirt for sale: http://ingebrigtsen.no/no.php
  and http://lars.ingebrigtsen.no/2013/08/twenty-years-of-september.html