bug-gnu-emacs
[Top][All Lists]
Advanced

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

bug#24201: 25.1.50; TLS connections sometimes hang


From: Lars Ingebrigtsen
Subject: bug#24201: 25.1.50; TLS connections sometimes hang
Date: Mon, 24 Jun 2019 15:25:52 +0200
User-agent: Gnus/5.13 (Gnus v5.13) Emacs/27.0.50 (gnu/linux)

I've now started looking at this again, and is running Emacs under gdb.

Last night, I got the hang again.  I C-z'd in gdb (i.e., SIGTSTP), and
then did "finish" until it returned sufficiently that we got back to the
hang, and the I repeated, the procedure a couple of times, until the
file "finish" returned to Emacs and Emacs was un-hung.

These hangs usually last for about a minute or so, with intervention
with gdb or not, so I would guess that the code stops hanging when the
peer finally gives up on the connection and hangs up or something.

Does the output from gdb have any smoking gun about what's making this
semi-infloop in accept-process-output?

(In case nobody remembers what this bug report is about: Sometimes, in
rare circumstances (like once every other day), when opening a TLS
connection from a timer (or probably any other asynchronous context),
and there's other TLS traffic already in happening, opening a new TLS
connection will hang.  I have no repeatable test case, though.)

Thread 1 "emacs" received signal SIGTSTP, Stopped (user).
pthread_sigmask (how=how@entry=0, newmask=<optimized out>, 
    newmask@entry=0x7fffffffa500, oldmask=oldmask@entry=0x7fffffffa5a0)
    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" (0xffffb198)
"network-stream-get-response" (0xffffb428)
"network-stream-open-starttls" (0xffffb8d8)
"open-network-stream" (0xffffbbc0)
"nntp-open-connection" (0xffffc0a0)
"nntp-open-server" (0xffffc3a0)
"nntp-possibly-change-group" (0xffffca50)
"nntp-with-open-group-function" (0xffffccf0)
"nntp-request-article" (0xffffcf60)
"gnus-request-article" (0xffffd228)
"gnus-async-prefetch-article" (0xffffd538)
"apply" (0xffffd648)
"timer-event-handler" (0xffffd8f8)
(gdb) bt
#0  pthread_sigmask (how=how@entry=0, newmask=<optimized out>, 
    newmask@entry=0x7fffffffa500, oldmask=oldmask@entry=0x7fffffffa5a0)
    at ../sysdeps/unix/sysv/linux/pthread_sigmask.c:50
#1  0x00005555556858be in block_interrupt_signal (
    oldset=oldset@entry=0x7fffffffa5a0) at sysdep.c:873
#2  0x000055555574cbed in really_call_select (arg=0x7fffffffa640)
    at thread.c:581
#3  0x000055555574d1d9 in thread_select (func=<optimized out>, 
    max_fds=max_fds@entry=23, rfds=rfds@entry=0x7fffffffa710, 
    wfds=wfds@entry=0x7fffffffa790, efds=efds@entry=0x0, 
    timeout=timeout@entry=0x7fffffffad60, sigmask=0x0) at thread.c:616
#4  0x000055555576aa75 in xg_select (fds_lim=23, 
    rfds=rfds@entry=0x7fffffffae90, wfds=wfds@entry=0x7fffffffaf10, 
    efds=efds@entry=0x0, timeout=timeout@entry=0x7fffffffad60, 
    sigmask=sigmask@entry=0x0) at xgselect.c:117
#5  0x000055555572bb97 in 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=0x555556830280, just_wait_proc=0)
    at process.c:5427
#6  0x000055555572d45b in Faccept_process_output (process=XIL(0x555556830285), 
    seconds=<optimized out>, millisec=<optimized out>, 
---Type <return> to continue, or q <return> to quit---q
just_this_one=<optimized Quit
(gdb) finish
Run till exit from #0  pthread_sigmask (how=how@entry=0, 
    newmask=<optimized out>, newmask@entry=0x7fffffffa500, 
    oldmask=oldmask@entry=0x7fffffffa5a0)
    at ../sysdeps/unix/sysv/linux/pthread_sigmask.c:50
block_interrupt_signal (oldset=oldset@entry=0x7fffffffa5a0) at sysdep.c:874
warning: Source file is more recent than executable.
874       pthread_sigmask (SIG_SETMASK, oldset, 0);
Value returned is $6 = 0
(gdb) finish
Run till exit from #0  block_interrupt_signal (
    oldset=oldset@entry=0x7fffffffa5a0) at sysdep.c:874
really_call_select (arg=0x7fffffffa640) at thread.c:583
583       release_global_lock ();
(gdb) finish
Run till exit from #0  really_call_select (arg=0x7fffffffa640) at thread.c:583
thread_select (func=<optimized out>, max_fds=max_fds@entry=23, 
    rfds=rfds@entry=0x7fffffffa710, wfds=wfds@entry=0x7fffffffa790, 
    efds=efds@entry=0x0, timeout=timeout@entry=0x7fffffffad60, sigmask=0x0)
    at thread.c:618
618     }
(gdb) finish
Run till exit from #0  thread_select (func=<optimized out>, 
    max_fds=max_fds@entry=23, rfds=rfds@entry=0x7fffffffa710, 
    wfds=wfds@entry=0x7fffffffa790, efds=efds@entry=0x0, 
    timeout=timeout@entry=0x7fffffffad60, sigmask=0x0) at thread.c:618
xg_select (fds_lim=23, rfds=rfds@entry=0x7fffffffae90, 
    wfds=wfds@entry=0x7fffffffaf10, efds=efds@entry=0x0, 
    timeout=timeout@entry=0x7fffffffad60, sigmask=sigmask@entry=0x0)
    at xgselect.c:120
120       if (nfds < 0)
Value returned is $7 = 3
(gdb) finish
Run till exit from #0  xg_select (fds_lim=23, rfds=rfds@entry=0x7fffffffae90, 
    wfds=wfds@entry=0x7fffffffaf10, efds=efds@entry=0x0, 
    timeout=timeout@entry=0x7fffffffad60, 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=0x555556830280, just_wait_proc=0)
    at process.c:5447
5447              if (nfds == 0)
Value returned is $8 = 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=0x555556830280, just_wait_proc=0)
    at process.c:5447
Faccept_process_output (process=XIL(0x555556830285), seconds=<optimized out>, 
    millisec=<optimized out>, just_this_one=<optimized out>) at process.c:4715
4715         ? Qnil : Qt);
Value returned is $9 = 74
(gdb) finish
Run till exit from #0  Faccept_process_output (process=XIL(0x555556830285), 
    seconds=<optimized out>, millisec=<optimized out>, 
    just_this_one=<optimized out>) at process.c:4715
0x00005555556ea3d9 in Ffuncall (nargs=3, args=args@entry=0x7fffffffb190)
    at eval.c:2803
2803        val = funcall_subr (XSUBR (fun), numargs, args + 1);
Value returned is $10 = (union Lisp_X *) 0xc5a0
(gdb) finish
Run till exit from #0  0x00005555556ea3d9 in Ffuncall (nargs=3, 
    args=args@entry=0x7fffffffb190) at eval.c:2803
0x0000555555720e60 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
warning: Source file is more recent than executable.
633                 TOP = Ffuncall (op + 1, &TOP);
Value returned is $11 = (union Lisp_X *) 0xc5a0
(gdb) finish
Run till exit from #0  0x0000555555720e60 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=0x7fffffffb420) at eval.c:2826
2826      lisp_eval_depth--;
Value returned is $12 = (union Lisp_X *) 0x0
(gdb) finish
Run till exit from #0  Ffuncall (nargs=4, args=args@entry=0x7fffffffb420)
    at eval.c:2826
0x0000555555720e60 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 $13 = (union Lisp_X *) 0x0
(gdb) finish
Run till exit from #0  0x0000555555720e60 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).
pthread_sigmask (how=how@entry=0, newmask=<optimized out>, 
    newmask@entry=0x7fffffffa800, oldmask=oldmask@entry=0x7fffffffa8a0)
    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" (0xffffb498)
"network-stream-get-response" (0xffffb728)
"network-stream-open-starttls" (0xffffbbd8)
"open-network-stream" (0xffffbec0)
"nntp-open-connection" (0xffffc3a0)
"nntp-possibly-change-group" (0xffffca50)
"nntp-with-open-group-function" (0xffffccf0)
"nntp-request-article" (0xffffcf60)
"gnus-request-article" (0xffffd228)
"gnus-async-prefetch-article" (0xffffd538)
"apply" (0xffffd648)
"timer-event-handler" (0xffffd8f8)
(gdb) finish
Run till exit from #0  pthread_sigmask (how=how@entry=0, 
    newmask=<optimized out>, newmask@entry=0x7fffffffa800, 
    oldmask=oldmask@entry=0x7fffffffa8a0)
    at ../sysdeps/unix/sysv/linux/pthread_sigmask.c:50
block_interrupt_signal (oldset=oldset@entry=0x7fffffffa8a0) at sysdep.c:874
874       pthread_sigmask (SIG_SETMASK, oldset, 0);
Value returned is $14 = 0
(gdb) finish
Run till exit from #0  block_interrupt_signal (
    oldset=oldset@entry=0x7fffffffa8a0) at sysdep.c:874
really_call_select (arg=0x7fffffffa940) at thread.c:583
583       release_global_lock ();
(gdb) finish
Run till exit from #0  really_call_select (arg=0x7fffffffa940) at thread.c:583
thread_select (func=<optimized out>, max_fds=max_fds@entry=23, 
    rfds=rfds@entry=0x7fffffffaa10, wfds=wfds@entry=0x7fffffffaa90, 
    efds=efds@entry=0x0, timeout=timeout@entry=0x7fffffffb060, sigmask=0x0)
    at thread.c:618
618     }
(gdb) finish
Run till exit from #0  thread_select (func=<optimized out>, 
    max_fds=max_fds@entry=23, rfds=rfds@entry=0x7fffffffaa10, 
    wfds=wfds@entry=0x7fffffffaa90, efds=efds@entry=0x0, 
    timeout=timeout@entry=0x7fffffffb060, sigmask=0x0) at thread.c:618
xg_select (fds_lim=23, rfds=rfds@entry=0x7fffffffb190, 
    wfds=wfds@entry=0x7fffffffb210, efds=efds@entry=0x0, 
    timeout=timeout@entry=0x7fffffffb060, sigmask=sigmask@entry=0x0)
    at xgselect.c:120
120       if (nfds < 0)
Value returned is $15 = 3
(gdb) finish
Run till exit from #0  xg_select (fds_lim=23, rfds=rfds@entry=0x7fffffffb190, 
    wfds=wfds@entry=0x7fffffffb210, efds=efds@entry=0x0, 
    timeout=timeout@entry=0x7fffffffb060, 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=0x55555b23b750, just_wait_proc=0)
    at process.c:5447
5447              if (nfds == 0)
Value returned is $16 = 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=0x55555b23b750, just_wait_proc=0)
    at process.c:5447
Faccept_process_output (process=XIL(0x55555b23b755), seconds=<optimized out>, 
    millisec=<optimized out>, just_this_one=<optimized out>) at process.c:4715
4715         ? Qnil : Qt);
Value returned is $17 = 74
(gdb) finish
Run till exit from #0  Faccept_process_output (process=XIL(0x55555b23b755), 
    seconds=<optimized out>, millisec=<optimized out>, 
    just_this_one=<optimized out>) at process.c:4715
0x00005555556ea3d9 in Ffuncall (nargs=3, args=args@entry=0x7fffffffb490)
    at eval.c:2803
2803        val = funcall_subr (XSUBR (fun), numargs, args + 1);
Value returned is $18 = (union Lisp_X *) 0xc5a0
(gdb) finish
Run till exit from #0  0x00005555556ea3d9 in Ffuncall (nargs=3, 
    args=args@entry=0x7fffffffb490) at eval.c:2803
0x0000555555720e60 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 $19 = (union Lisp_X *) 0xc5a0
(gdb) finish
Run till exit from #0  0x0000555555720e60 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=0x7fffffffb720) at eval.c:2826
2826      lisp_eval_depth--;
Value returned is $20 = (union Lisp_X *) 0x0
(gdb) finish
Run till exit from #0  Ffuncall (nargs=4, args=args@entry=0x7fffffffb720)
    at eval.c:2826
0x0000555555720e60 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 $21 = (union Lisp_X *) 0x0
(gdb) finish
Run till exit from #0  0x0000555555720e60 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

^Z
Thread 1 "emacs" received signal SIGTSTP, Stopped (user).
0x00005555556c6c53 in vectorlike_nbytes (hdr=0x555556d1dd20) at alloc.c:2964
2964      ptrdiff_t size = hdr->size & ~ARRAY_MARK_FLAG;
(gdb) finish
Run till exit from #0  0x00005555556c6c53 in vectorlike_nbytes (
    hdr=0x555556d1dd20) at alloc.c:2964
sweep_vectors () at alloc.c:3073
3073                  gcstat.total_vector_slots += nbytes / word_size;
Value returned is $22 = 1040
(gdb) finish
Run till exit from #0  sweep_vectors () at alloc.c:3073
gc_sweep () at alloc.c:6973
6973      pdumper_clear_marks ();
(gdb) finish
Run till exit from #0  gc_sweep () at alloc.c:6973
garbage_collect_1 (gcst=0x7fffffffaa30) at alloc.c:5917
5917      unmark_main_thread ();
(gdb) finish
Run till exit from #0  garbage_collect_1 (gcst=0x7fffffffaa30) at alloc.c:5917
garbage_collect () at alloc.c:5990
5990    }
Value returned is $23 = true
(gdb) finish
Run till exit from #0  garbage_collect () at alloc.c:5990
Ffuncall (nargs=nargs@entry=2, args=args@entry=0x7fffffffab20) at eval.c:2789
2789      if (debug_on_next_call)
(gdb) finish
Run till exit from #0  Ffuncall (nargs=nargs@entry=2, 
    args=args@entry=0x7fffffffab20) at eval.c:2789
call1 (fn=fn@entry=XIL(0xc960), arg1=arg1@entry=XIL(0x5555570ee915))
    at eval.c:2657
2657    }
Value returned is $24 = (union Lisp_X *) 0x0
(gdb) finish
Run till exit from #0  call1 (fn=fn@entry=XIL(0xc960), 
    arg1=arg1@entry=XIL(0x5555570ee915)) at eval.c:2657
timer_check_2 (idle_timers=XIL(0), timers=XIL(0x555571081263))
    at keyboard.c:4309
4309                  unbind_to (count, Qnil);
Value returned is $25 = (union Lisp_X *) 0x0
(gdb) finish
Run till exit from #0  timer_check_2 (idle_timers=XIL(0), 
    timers=XIL(0x555571081263)) at keyboard.c:4309
timer_check () at keyboard.c:4368
4368          nexttime = timer_check_2 (timers, idle_timers);
(gdb) finish
Run till exit from #0  timer_check () at keyboard.c:4368
0x0000555555673bf9 in readable_events (flags=flags@entry=1) at keyboard.c:3367
3367        timer_check ();
Value returned is $26 = {tv_sec = 0, tv_nsec = 58418057}
(gdb) finish
Run till exit from #0  0x0000555555673bf9 in readable_events (
    flags=flags@entry=1) at keyboard.c:3367
0x0000555555674638 in get_input_pending (flags=flags@entry=1)
    at keyboard.c:6769
6769      input_pending = (!NILP (Vquit_flag) || readable_events (flags));
Value returned is $27 = true
(gdb) finish
Run till exit from #0  0x0000555555674638 in get_input_pending (
    flags=flags@entry=1) at keyboard.c:6769
swallow_events (do_display=do_display@entry=false) at keyboard.c:4115
4115      if (!input_pending && timers_run != old_timers_run && do_display)
Value returned is $28 = true
(gdb) finish
Run till exit from #0  swallow_events (do_display=do_display@entry=false)
    at keyboard.c:4115
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=0x555556853170, just_wait_proc=0)
    at process.c:5605
5605          if (! NILP (wait_for_cell) && ! NILP (XCAR (wait_for_cell)))
(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=0x555556853170, just_wait_proc=0)
    at process.c:5605
Faccept_process_output (process=XIL(0x555556853175), seconds=<optimized out>, 
    millisec=<optimized out>, just_this_one=<optimized out>) at process.c:4715
4715         ? Qnil : Qt);
Value returned is $29 = 74
(gdb) finish
Run till exit from #0  Faccept_process_output (process=XIL(0x555556853175), 
    seconds=<optimized out>, millisec=<optimized out>, 
    just_this_one=<optimized out>) at process.c:4715
0x00005555556ea3d9 in Ffuncall (nargs=3, args=args@entry=0x7fffffffb190)
    at eval.c:2803
2803        val = funcall_subr (XSUBR (fun), numargs, args + 1);
Value returned is $30 = (union Lisp_X *) 0xc5a0
(gdb) finish
Run till exit from #0  0x00005555556ea3d9 in Ffuncall (nargs=3, 
    args=args@entry=0x7fffffffb190) at eval.c:2803
0x0000555555720e60 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 $31 = (union Lisp_X *) 0xc5a0
(gdb) finish
Run till exit from #0  0x0000555555720e60 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=0x7fffffffb420) at eval.c:2826
2826      lisp_eval_depth--;
Value returned is $32 = (union Lisp_X *) 0x0
(gdb) finish
Run till exit from #0  Ffuncall (nargs=4, args=args@entry=0x7fffffffb420)
    at eval.c:2826
0x0000555555720e60 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 $33 = (union Lisp_X *) 0x0
(gdb) finish
Run till exit from #0  0x0000555555720e60 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).
0x00005555556ca268 in mark_object (arg=<optimized out>) at alloc.c:6571
6571            if (NILP (ptr->u.s.u.cdr))
(gdb) 



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






reply via email to

[Prev in Thread] Current Thread [Next in Thread]