bug#24201: 25.1.50; TLS connections sometimes hang

[Lars Ingebrigtsen]

OK, got another one.  I hit C-g a bunch in Emacs first, but got no
response, and then TSTP-d the process:

Thread 1 "emacs" received signal SIGTSTP, Stopped (user).
pthread_sigmask (how=how@entry=0, newmask=<optimized out>, 
    newmask@entry=0x7fffffffa550, oldmask=oldmask@entry=0x7fffffffa5f0)
    at ../sysdeps/unix/sysv/linux/pthread_sigmask.c:50
50      ../sysdeps/unix/sysv/linux/pthread_sigmask.c: No such file or directory.
(gdb) finish
Run till exit from #0  pthread_sigmask (how=how@entry=0, 
    newmask=<optimized out>, newmask@entry=0x7fffffffa550, 
    oldmask=oldmask@entry=0x7fffffffa5f0)
    at ../sysdeps/unix/sysv/linux/pthread_sigmask.c:50
block_interrupt_signal (oldset=oldset@entry=0x7fffffffa5f0) at sysdep.c:868
868     }
Value returned is $21 = 0
(gdb) finish
Run till exit from #0  block_interrupt_signal (
    oldset=oldset@entry=0x7fffffffa5f0) at sysdep.c:868
really_call_select (arg=0x7fffffffa690) at thread.c:594
594       if (self->not_holding_lock)
(gdb) finish
Run till exit from #0  really_call_select (arg=0x7fffffffa690) at thread.c:594
thread_select (func=<optimized out>, max_fds=max_fds@entry=22, 
    rfds=rfds@entry=0x7fffffffa760, wfds=wfds@entry=0x7fffffffa7e0, 
    efds=efds@entry=0x0, timeout=timeout@entry=0x7fffffffadb0, sigmask=0x0)
    at thread.c:618
618     }
(gdb) finish
Run till exit from #0  thread_select (func=<optimized out>, 
    max_fds=max_fds@entry=22, rfds=rfds@entry=0x7fffffffa760, 
    wfds=wfds@entry=0x7fffffffa7e0, efds=efds@entry=0x0, 
    timeout=timeout@entry=0x7fffffffadb0, sigmask=0x0) at thread.c:618
xg_select (fds_lim=22, rfds=rfds@entry=0x7fffffffaee0, 
    wfds=wfds@entry=0x7fffffffaf60, efds=efds@entry=0x0, 
    timeout=timeout@entry=0x7fffffffadb0, sigmask=sigmask@entry=0x0)
    at xgselect.c:120
120       if (nfds < 0)
Value returned is $22 = 1
(gdb) finish
Run till exit from #0  xg_select (fds_lim=22, rfds=rfds@entry=0x7fffffffaee0, 
    wfds=wfds@entry=0x7fffffffaf60, efds=efds@entry=0x0, 
    timeout=timeout@entry=0x7fffffffadb0, sigmask=sigmask@entry=0x0)
    at xgselect.c:120
wait_reading_process_output (time_limit=<optimized out>, 
    nsecs=<optimized out>, read_kbd=read_kbd@entry=0, 
    do_display=do_display@entry=false, 
    wait_for_cell=wait_for_cell@entry=XIL(0), 
    wait_proc=wait_proc@entry=0x55555c0176e0, just_wait_proc=0)
    at process.c:5447
5447              if (nfds == 0)
Value returned is $23 = 1
(gdb) finish
Run till exit from #0  wait_reading_process_output (
    time_limit=<optimized out>, nsecs=<optimized out>, 
    read_kbd=read_kbd@entry=0, do_display=do_display@entry=false, 
    wait_for_cell=wait_for_cell@entry=XIL(0), 
    wait_proc=wait_proc@entry=0x55555c0176e0, just_wait_proc=0)
    at process.c:5447
Faccept_process_output (process=XIL(0x55555c0176e5), seconds=<optimized out>, 
    millisec=<optimized out>, just_this_one=<optimized out>) at process.c:4715
4715         ? Qnil : Qt);
Value returned is $24 = 74
(gdb) finish
Run till exit from #0  Faccept_process_output (process=XIL(0x55555c0176e5), 
    seconds=<optimized out>, millisec=<optimized out>, 
    just_this_one=<optimized out>) at process.c:4715
0x00005555556ea7c9 in Ffuncall (nargs=3, args=args@entry=0x7fffffffb1e0)
    at eval.c:2803
2803        val = funcall_subr (XSUBR (fun), numargs, args + 1);
Value returned is $25 = (union Lisp_X *) 0xc5a0
(gdb) finish
Run till exit from #0  0x00005555556ea7c9 in Ffuncall (nargs=3, 
    args=args@entry=0x7fffffffb1e0) at eval.c:2803
0x0000555555721250 in exec_byte_code (bytestr=<optimized out>, 
    vector=<optimized out>, maxdepth=<optimized out>, 
    args_template=<optimized out>, nargs=nargs@entry=3, args=<optimized out>, 
    args@entry=0x35) at bytecode.c:633
633                 TOP = Ffuncall (op + 1, &TOP);
Value returned is $26 = (union Lisp_X *) 0xc5a0
(gdb) finish
Run till exit from #0  0x0000555555721250 in exec_byte_code (
    bytestr=<optimized out>, vector=<optimized out>, maxdepth=<optimized out>, 
    args_template=<optimized out>, nargs=nargs@entry=3, args=<optimized out>, 
    args@entry=0x35) at bytecode.c:633
Ffuncall (nargs=4, args=args@entry=0x7fffffffb470) at eval.c:2826
2826      lisp_eval_depth--;
Value returned is $27 = (union Lisp_X *) 0x0

---
OK, so here's I'm at the lisp_eval_depth--.
---

(gdb) p args[0]
$28 = XIL(0x1401750)
(gdb) xsymbol 
$29 = (struct Lisp_Symbol *) 0x555557199570
"network-stream-get-response"
(gdb) xbacktrace 
"network-stream-get-response" (0xffffb478)
"network-stream-open-starttls" (0xffffb928)
"open-network-stream" (0xffffbc10)
"nntp-open-connection" (0xffffc0f0)
"nntp-open-server" (0xffffc3f0)
"nntp-possibly-change-group" (0xffffcaa0)
"nntp-with-open-group-function" (0xffffcd40)
"nntp-request-article" (0xffffcfb0)
"gnus-request-article" (0xffffd278)
"gnus-async-prefetch-article" (0xffffd588)
"apply" (0xffffd698)
"timer-event-handler" (0xffffd948)


And then there's a couple more of the same things: Emacs continues after
a few more finishes, and I TSTP it:


(gdb) finish
Run till exit from #0  Ffuncall (nargs=4, args=args@entry=0x7fffffffb470)
    at eval.c:2826
0x0000555555721250 in exec_byte_code (bytestr=<optimized out>, 
    vector=<optimized out>, maxdepth=<optimized out>, 
    args_template=<optimized out>, nargs=nargs@entry=5, args=<optimized out>, 
    args@entry=0x34) at bytecode.c:633
633                 TOP = Ffuncall (op + 1, &TOP);
Value returned is $30 = (union Lisp_X *) 0x0
(gdb) finish
Run till exit from #0  0x0000555555721250 in exec_byte_code (
    bytestr=<optimized out>, vector=<optimized out>, maxdepth=<optimized out>, 
    args_template=<optimized out>, nargs=nargs@entry=5, args=<optimized out>, 
    args@entry=0x34) at bytecode.c:633

^Z
Thread 1 "emacs" received signal SIGTSTP, Stopped (user).
0x00005555556ca609 in cons_marked_p (c=0x55556da37da0) at alloc.c:3774
3774        : XCONS_MARKED_P (c);
(gdb) xbacktrace 
"Automatic GC" (0x0)
"timer-event-handler" (0xffffaec8)
"accept-process-output" (0xffffb4e8)
"network-stream-get-response" (0xffffb778)
"network-stream-open-starttls" (0xffffbc28)
"open-network-stream" (0xffffbf10)
"nntp-open-connection" (0xffffc3f0)
"nntp-possibly-change-group" (0xffffcaa0)
"nntp-with-open-group-function" (0xffffcd40)
"nntp-request-article" (0xffffcfb0)
"gnus-request-article" (0xffffd278)
"gnus-async-prefetch-article" (0xffffd588)
"apply" (0xffffd698)
"timer-event-handler" (0xffffd948)
(gdb) finish
Run till exit from #0  0x00005555556ca609 in cons_marked_p (c=0x55556da37da0)
    at alloc.c:3774
mark_object (arg=<optimized out>) at alloc.c:6566
6566            if (cons_marked_p (ptr))
(gdb) finish
Run till exit from #0  mark_object (arg=<optimized out>) at alloc.c:6566
mark_object (arg=<optimized out>) at alloc.c:6580
6580            if (cdr_count == mark_object_loop_halt)
(gdb) finish
Run till exit from #0  mark_object (arg=<optimized out>) at alloc.c:6580
mark_object (arg=<optimized out>) at alloc.c:6580
6580            if (cdr_count == mark_object_loop_halt)
(gdb) finish
Run till exit from #0  mark_object (arg=<optimized out>) at alloc.c:6580
mark_object (arg=<optimized out>) at alloc.c:6580
6580            if (cdr_count == mark_object_loop_halt)
(gdb) finish
Run till exit from #0  mark_object (arg=<optimized out>) at alloc.c:6580
mark_object (arg=<optimized out>) at alloc.c:6580
6580            if (cdr_count == mark_object_loop_halt)
(gdb) finish
Run till exit from #0  mark_object (arg=<optimized out>) at alloc.c:6580
mark_localized_symbol (ptr=<optimized out>) at alloc.c:6228
6228      mark_object (blv->defcell);
(gdb) finish
Run till exit from #0  mark_localized_symbol (ptr=<optimized out>)
    at alloc.c:6228
mark_object (arg=<optimized out>) at alloc.c:6544
6544                break;
(gdb) finish
Run till exit from #0  mark_object (arg=<optimized out>) at alloc.c:6544
mark_vectorlike (header=0x555556e35a20) at alloc.c:6105
6105      for (i = 0; i < size; i++) /* ...and then mark its elements.  */
(gdb) finish
Run till exit from #0  mark_vectorlike (header=0x555556e35a20) at alloc.c:6105
mark_object (arg=<optimized out>) at alloc.c:6531
6531            mark_object (ptr->u.s.plist);
(gdb) finish
Run till exit from #0  mark_object (arg=<optimized out>) at alloc.c:6531
mark_vectorlike (header=0x555556e51a40) at alloc.c:6105
6105      for (i = 0; i < size; i++) /* ...and then mark its elements.  */
(gdb) finish
Run till exit from #0  mark_vectorlike (header=0x555556e51a40) at alloc.c:6105
mark_object (arg=<optimized out>) at alloc.c:6531
6531            mark_object (ptr->u.s.plist);
(gdb) finish
Run till exit from #0  mark_object (arg=<optimized out>) at alloc.c:6531
mark_vectorlike (header=0x555556e5a7b0) at alloc.c:6105
6105      for (i = 0; i < size; i++) /* ...and then mark its elements.  */
(gdb) finish
Run till exit from #0  mark_vectorlike (header=0x555556e5a7b0) at alloc.c:6105
mark_object (arg=<optimized out>) at alloc.c:6531
6531            mark_object (ptr->u.s.plist);

But I landed inside a gc, so I just cont:

(gdb) cont
Continuing.
^Z
Thread 1 "emacs" received signal SIGTSTP, Stopped (user).
pthread_sigmask (how=how@entry=0, newmask=<optimized out>, 
    newmask@entry=0x7fffffffa550, oldmask=oldmask@entry=0x7fffffffa5f0)
    at ../sysdeps/unix/sysv/linux/pthread_sigmask.c:50
50      ../sysdeps/unix/sysv/linux/pthread_sigmask.c: No such file or directory.
(gdb) finish
Run till exit from #0  pthread_sigmask (how=how@entry=0, 
    newmask=<optimized out>, newmask@entry=0x7fffffffa550, 
    oldmask=oldmask@entry=0x7fffffffa5f0)
    at ../sysdeps/unix/sysv/linux/pthread_sigmask.c:50
block_interrupt_signal (oldset=oldset@entry=0x7fffffffa5f0) at sysdep.c:868
868     }
Value returned is $31 = 0
(gdb) cont
Continuing.
^Z

And then a new TSTP:

Thread 1 "emacs" received signal SIGTSTP, Stopped (user).
pthread_sigmask (how=how@entry=0, newmask=<optimized out>, 
    newmask@entry=0x7fffffffa850, oldmask=oldmask@entry=0x7fffffffa8f0)
    at ../sysdeps/unix/sysv/linux/pthread_sigmask.c:50
50      ../sysdeps/unix/sysv/linux/pthread_sigmask.c: No such file or directory.
(gdb) xbacktrace 
"accept-process-output" (0xffffb4e8)
"network-stream-get-response" (0xffffb778)
"network-stream-open-starttls" (0xffffbc28)
"open-network-stream" (0xffffbf10)
"nntp-open-connection" (0xffffc3f0)
"nntp-possibly-change-group" (0xffffcaa0)
"nntp-with-open-group-function" (0xffffcd40)
"nntp-request-article" (0xffffcfb0)
"gnus-request-article" (0xffffd278)
"gnus-async-prefetch-article" (0xffffd588)
"apply" (0xffffd698)
"timer-event-handler" (0xffffd948)
(gdb) finish
Run till exit from #0  pthread_sigmask (how=how@entry=0, 
    newmask=<optimized out>, newmask@entry=0x7fffffffa850, 
    oldmask=oldmask@entry=0x7fffffffa8f0)
    at ../sysdeps/unix/sysv/linux/pthread_sigmask.c:50
block_interrupt_signal (oldset=oldset@entry=0x7fffffffa8f0) at sysdep.c:868
868     }
Value returned is $32 = 0
(gdb) finish
Run till exit from #0  block_interrupt_signal (
    oldset=oldset@entry=0x7fffffffa8f0) at sysdep.c:868
really_call_select (arg=0x7fffffffa990) at thread.c:583
583       release_global_lock ();
(gdb) finish
Run till exit from #0  really_call_select (arg=0x7fffffffa990) at thread.c:583
thread_select (func=<optimized out>, max_fds=max_fds@entry=22, 
    rfds=rfds@entry=0x7fffffffaa60, wfds=wfds@entry=0x7fffffffaae0, 
    efds=efds@entry=0x0, timeout=timeout@entry=0x7fffffffb0b0, sigmask=0x0)
    at thread.c:618
618     }
(gdb) finish
Run till exit from #0  thread_select (func=<optimized out>, 
    max_fds=max_fds@entry=22, rfds=rfds@entry=0x7fffffffaa60, 
    wfds=wfds@entry=0x7fffffffaae0, efds=efds@entry=0x0, 
    timeout=timeout@entry=0x7fffffffb0b0, sigmask=0x0) at thread.c:618
xg_select (fds_lim=22, rfds=rfds@entry=0x7fffffffb1e0, 
    wfds=wfds@entry=0x7fffffffb260, efds=efds@entry=0x0, 
    timeout=timeout@entry=0x7fffffffb0b0, sigmask=sigmask@entry=0x0)
    at xgselect.c:120
120       if (nfds < 0)
Value returned is $33 = 3
(gdb) finish
Run till exit from #0  xg_select (fds_lim=22, rfds=rfds@entry=0x7fffffffb1e0, 
    wfds=wfds@entry=0x7fffffffb260, efds=efds@entry=0x0, 
    timeout=timeout@entry=0x7fffffffb0b0, sigmask=sigmask@entry=0x0)
    at xgselect.c:120
wait_reading_process_output (time_limit=<optimized out>, 
    nsecs=<optimized out>, read_kbd=read_kbd@entry=0, 
    do_display=do_display@entry=false, 
    wait_for_cell=wait_for_cell@entry=XIL(0), 
    wait_proc=wait_proc@entry=0x555560255dc0, just_wait_proc=0)
    at process.c:5447
5447              if (nfds == 0)
Value returned is $34 = 2
(gdb) finish
Run till exit from #0  wait_reading_process_output (
    time_limit=<optimized out>, nsecs=<optimized out>, 
    read_kbd=read_kbd@entry=0, do_display=do_display@entry=false, 
    wait_for_cell=wait_for_cell@entry=XIL(0), 
    wait_proc=wait_proc@entry=0x555560255dc0, just_wait_proc=0)
    at process.c:5447
Faccept_process_output (process=XIL(0x555560255dc5), seconds=<optimized out>, 
    millisec=<optimized out>, just_this_one=<optimized out>) at process.c:4715
4715         ? Qnil : Qt);
Value returned is $35 = 74
(gdb) finish
Run till exit from #0  Faccept_process_output (process=XIL(0x555560255dc5), 
    seconds=<optimized out>, millisec=<optimized out>, 
    just_this_one=<optimized out>) at process.c:4715
0x00005555556ea7c9 in Ffuncall (nargs=3, args=args@entry=0x7fffffffb4e0)
    at eval.c:2803
2803        val = funcall_subr (XSUBR (fun), numargs, args + 1);
Value returned is $36 = (union Lisp_X *) 0xc5a0
(gdb) finish
Run till exit from #0  0x00005555556ea7c9 in Ffuncall (nargs=3, 
    args=args@entry=0x7fffffffb4e0) at eval.c:2803
0x0000555555721250 in exec_byte_code (bytestr=<optimized out>, 
    vector=<optimized out>, maxdepth=<optimized out>, 
    args_template=<optimized out>, nargs=nargs@entry=3, args=<optimized out>, 
    args@entry=0x31) at bytecode.c:633
633                 TOP = Ffuncall (op + 1, &TOP);
Value returned is $37 = (union Lisp_X *) 0xc5a0
(gdb) finish
Run till exit from #0  0x0000555555721250 in exec_byte_code (
    bytestr=<optimized out>, vector=<optimized out>, maxdepth=<optimized out>, 
    args_template=<optimized out>, nargs=nargs@entry=3, args=<optimized out>, 
    args@entry=0x31) at bytecode.c:633
Ffuncall (nargs=4, args=args@entry=0x7fffffffb770) at eval.c:2826
2826      lisp_eval_depth--;
Value returned is $38 = (union Lisp_X *) 0x0
(gdb) p args[0]
$39 = XIL(0x1401750)
(gdb) xsymbol 
$40 = (struct Lisp_Symbol *) 0x555557199570
"network-stream-get-response"
(gdb) xbacktrace 
"network-stream-get-response" (0xffffb778)
"network-stream-open-starttls" (0xffffbc28)
"open-network-stream" (0xffffbf10)
"nntp-open-connection" (0xffffc3f0)
"nntp-possibly-change-group" (0xffffcaa0)
"nntp-with-open-group-function" (0xffffcd40)
"nntp-request-article" (0xffffcfb0)
"gnus-request-article" (0xffffd278)
"gnus-async-prefetch-article" (0xffffd588)
"apply" (0xffffd698)
"timer-event-handler" (0xffffd948)

So this looks very similar to the first one.

(gdb) finish
Run till exit from #0  Ffuncall (nargs=4, args=args@entry=0x7fffffffb770)
    at eval.c:2826
0x0000555555721250 in exec_byte_code (bytestr=<optimized out>, 
    vector=<optimized out>, maxdepth=<optimized out>, 
    args_template=<optimized out>, nargs=nargs@entry=5, args=<optimized out>, 
    args@entry=0x30) at bytecode.c:633
633                 TOP = Ffuncall (op + 1, &TOP);
Value returned is $41 = (union Lisp_X *) 0x0
(gdb) finish
Run till exit from #0  0x0000555555721250 in exec_byte_code (
    bytestr=<optimized out>, vector=<optimized out>, maxdepth=<optimized out>, 
    args_template=<optimized out>, nargs=nargs@entry=5, args=<optimized out>, 
    args@entry=0x30) at bytecode.c:633
Ffuncall (nargs=2, args=args@entry=0x7fffffffbbd8) at eval.c:2826
2826      lisp_eval_depth--;
Value returned is $42 = (union Lisp_X *) 0x555559d0a544
(gdb) cont
Continuing.

And upon continuing, Emacs un-stuck with the following message:

Error running timer ‘gnus-async-prefetch-article’: (error "Server closed 
connection")


-- 
(domestic pets only, the antidote for overdose, milk.)
   bloggy blog: http://lars.ingebrigtsen.no