[tor-bugs] #23676 [Core Tor/Tor]: relay running 0.3.2.1-alpha-dev wedged: kist bug?

[Tor Bug Tracker & Wiki]

#23676: relay running 0.3.2.1-alpha-dev wedged: kist bug?
------------------------------+--------------------------------
     Reporter:  arma          |      Owner:  (none)
         Type:  defect        |     Status:  new
     Priority:  Medium        |  Milestone:  Tor: 0.3.2.x-final
    Component:  Core Tor/Tor  |    Version:
     Severity:  Normal        |   Keywords:
Actual Points:                |  Parent ID:
       Points:                |   Reviewer:
      Sponsor:                |
------------------------------+--------------------------------
 moria1 running "0.3.2.1-alpha-dev (git-a1f31c0671c82f95)" last wrote to
 its info-level log this morning at 05:15:
 {{{
 Sep 27 05:15:09.482 [info] connection_close_immediate(): fd 334, type OR,
 state open, 146672 bytes on outbuf.
 }}}

 That was 9 hours ago.

 The process is still alive, and it's using 100% cpu.

 I did a gdb attach, and it looks like it is doing...stuff. Here are three
 snapshots:
 {{{
 #0  channel_flush_some_cells (chan=0x7f2e04c84c80, num_cells=1)
     at src/or/channel.c:2355
 #1  0x00007f2df60bd915 in kist_scheduler_run () at
 src/or/scheduler_kist.c:589
 #2  0x00007f2df60bb7e2 in scheduler_evt_callback (fd=<value optimized
 out>,·
     events=<value optimized out>, arg=<value optimized out>)
     at src/or/scheduler.c:215
 #3  0x00007f2df6201040 in event_process_active_single_queue ()
 #4  0x00007f2df6201610 in event_process_active ()
 #5  0x00007f2df6201d74 in event_base_loop ()
 #6  0x00007f2df60530dd in run_main_loop_once () at src/or/main.c:2631
 #7  run_main_loop_until_done () at src/or/main.c:2685
 #8  do_main_loop () at src/or/main.c:2598
 #9  0x00007f2df605421d in tor_main (argc=<value optimized out>,·
     argv=<value optimized out>) at src/or/main.c:3780
 #10 0x00007f2df604fd99 in main (argc=<value optimized out>,·
     argv=<value optimized out>) at src/or/tor_main.c:34
 }}}

 {{{
 #0  channel_more_to_flush (chan=0x7f2e04c84c80) at src/or/channel.c:2609
 #1  0x00007f2df60bd868 in kist_scheduler_run () at
 src/or/scheduler_kist.c:600
 #2  0x00007f2df60bb7e2 in scheduler_evt_callback (fd=<value optimized
 out>,·
     events=<value optimized out>, arg=<value optimized out>)
     at src/or/scheduler.c:215
 #3  0x00007f2df6201040 in event_process_active_single_queue ()
 #4  0x00007f2df6201610 in event_process_active ()
 #5  0x00007f2df6201d74 in event_base_loop ()
 #6  0x00007f2df60530dd in run_main_loop_once () at src/or/main.c:2631
 #7  run_main_loop_until_done () at src/or/main.c:2685
 #8  do_main_loop () at src/or/main.c:2598
 #9  0x00007f2df605421d in tor_main (argc=<value optimized out>,·
     argv=<value optimized out>) at src/or/main.c:3780
 #10 0x00007f2df604fd99 in main (argc=<value optimized out>,·
     argv=<value optimized out>) at src/or/tor_main.c:34
 }}}

 {{{
 #0  0x00007f2df60bd42e in socket_table_s_HT_FIND_P_ (
     chan=<value optimized out>, table=0x7f2df64f0ee0)
     at src/or/scheduler_kist.c:50
 #1  socket_table_s_HT_FIND (chan=<value optimized out>,
 table=0x7f2df64f0ee0)
     at src/or/scheduler_kist.c:51
 #2  socket_table_search (chan=<value optimized out>, table=0x7f2df64f0ee0)
     at src/or/scheduler_kist.c:168
 #3  0x00007f2df60bd4a9 in socket_can_write (chan=<value optimized out>,
     table=0x7f2df64f0ee0) at src/or/scheduler_kist.c:372
 #4  0x00007f2df60bd968 in kist_scheduler_run () at
 src/or/scheduler_kist.c:630
 #5  0x00007f2df60bb7e2 in scheduler_evt_callback (fd=<value optimized
 out>,
     events=<value optimized out>, arg=<value optimized out>)
     at src/or/scheduler.c:215
 #6  0x00007f2df6201040 in event_process_active_single_queue ()
 #7  0x00007f2df6201610 in event_process_active ()
 #8  0x00007f2df6201d74 in event_base_loop ()
 #9  0x00007f2df60530dd in run_main_loop_once () at src/or/main.c:2631
 #10 run_main_loop_until_done () at src/or/main.c:2685
 #11 do_main_loop () at src/or/main.c:2598
 #12 0x00007f2df605421d in tor_main (argc=<value optimized out>,
     argv=<value optimized out>) at src/or/main.c:3780
 #13 0x00007f2df604fd99 in main (argc=<value optimized out>,
     argv=<value optimized out>) at src/or/tor_main.c:34
 }}}

 David suggested that I try {{{strace -f -p PID -o /tmp/strace.log}}}, and
 I ran it for 30 seconds or so, and it produced this file:
 {{{
 13376 futex(0x7f2dff2de65c, FUTEX_WAIT_PRIVATE, 755787, NULL <unfinished
 ...>
 13375 futex(0x7f2dff2de65c, FUTEX_WAIT_PRIVATE, 755787, NULL <unfinished
 ...>
 13374 futex(0x7f2dff2de65c, FUTEX_WAIT_PRIVATE, 755787, NULL <unfinished
 ...>
 13373 futex(0x7f2dff2de65c, FUTEX_WAIT_PRIVATE, 755787, NULL <unfinished
 ...>
 13372 futex(0x7f2dff2de65c, FUTEX_WAIT_PRIVATE, 755787, NULL <unfinished
 ...>
 13371 futex(0x7f2dff2de65c, FUTEX_WAIT_PRIVATE, 755787, NULL <unfinished
 ...>
 13370 futex(0x7f2dff2de65c, FUTEX_WAIT_PRIVATE, 755787, NULL <unfinished
 ...>
 13369 futex(0x7f2dff2de65c, FUTEX_WAIT_PRIVATE, 755787, NULL <unfinished
 ...>
 13368 futex(0x7f2dff2de65c, FUTEX_WAIT_PRIVATE, 755787, NULL <detached
 ...>
 }}}

--
Ticket URL: <https://trac.torproject.org/projects/tor/ticket/23676>
Tor Bug Tracker & Wiki <https://trac.torproject.org/>
The Tor Project: anonymity online