kist on 0.3.2.1-alpha-dev beats its head against a wall trying to flush a conn that's closed

Closed (moved) Issue created 7 years ago by Roger Dingledine

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 ...>

kist on 0.3.2.1-alpha-dev beats its head against a wall trying to flush a conn that's closed

Linked items ... 0

Activity