[tor-bugs] #9862 [Tor]: Tor hangs if you ask it to open too many ORPorts

Tue Oct 1 22:31:40 UTC 2013

#9862: Tor hangs if you ask it to open too many ORPorts
------------------------+--------------------------------
     Reporter:  zwol    |      Owner:
         Type:  defect  |     Status:  new
     Priority:  normal  |  Milestone:  Tor: 0.2.5.x-final
    Component:  Tor     |    Version:  Tor: 0.2.4.17-rc
   Resolution:          |   Keywords:  tor-relay
Actual Points:          |  Parent ID:
       Points:          |
------------------------+--------------------------------

Comment (by zwol):

 This is interesting.  I think what we actually have here is a deadlock
 caused by STEM.

 All but one of the threads in the Tor process (there are nine) are blocked
 in `recv` and have the same stack trace (with different file descriptors):

 {{{
 #0  0x00007ff31c61c8bc in __libc_recv (fd=fd at entry=214, buf=<optimized
 out>,
     n=<optimized out>, flags=<optimized out>, flags at entry=0)
     at ../sysdeps/unix/sysv/linux/x86_64/recv.c:34
 #1  0x00007ff31d8f163a in recv (__flags=0, __n=552, __buf=0x7ff30f7f5940,
     __fd=214) at /usr/include/x86_64-linux-gnu/bits/socket2.h:45
 #2  read_all (fd=fd at entry=214, buf=buf at entry=0x7ff30f7f5940 "",
     count=count at entry=552, isSocket=isSocket at entry=1)
     at ../src/common/util.c:1685
 #3  0x00007ff31d8a79be in cpuworker_main (data=0x0,
 data at entry=0x7ff3080f7fd0)
     at ../src/or/cpuworker.c:428
 #4  0x00007ff31d8defe8 in tor_pthread_helper_fn (_data=0x0)
     at ../src/common/compat.c:2248
 #5  0x00007ff31c32bb50 in start_thread (arg=<optimized out>)
     at pthread_create.c:304
 #6  0x00007ff31c61ba7d in clone ()
     at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112
 }}}

 ... so I presume they are all CPU workers waiting for something to do.

 The remaining thread has this stack trace:

 {{{
 Program received signal SIGINT, Interrupt.
 0x00007ff31c60fb0d in write () at ../sysdeps/unix/syscall-template.S:82
 82      in ../sysdeps/unix/syscall-template.S
 (gdb) bt
 #0  0x00007ff31c60fb0d in write () at ../sysdeps/unix/syscall-
 template.S:82
 #1  0x00007ff31d8f152e in write_all (fd=1,
     buf=buf at entry=0x7fff49cb7650 "Oct 01 22:15:01.000 [notice] Your Tor
 server's identity key fingerprint is 'tbbscraperentry
 73EFD4FE8D5D2466ECBDCFAC11894A72A322FD3C'\n", count=count at entry=134,
 isSocket=0, isSocket at entry=1238070893)
     at ../src/common/util.c:1661
 #2  0x00007ff31d8e9fae in logv (severity=5, domain=<optimized out>,
     funcname=0x7ff31d920bb3 "init_keys", suffix=suffix at entry=0x0,
     format=format at entry=0x7ff31d9205f8 "Your Tor server's identity key
 fingerprint is '%s %s'", ap=ap at entry=0x7fff49cb9dc0) at
 ../src/common/log.c:417
 #3  0x00007ff31d8ea263 in log_fn_ (severity=severity at entry=5,
     domain=domain at entry=1, fn=fn at entry=0x7ff31d920bb3 "init_keys",
     format=format at entry=0x7ff31d9205f8 "Your Tor server's identity key
 fingerprint is '%s %s'") at ../src/common/log.c:455
 #4  0x00007ff31d822d15 in init_keys () at ../src/or/router.c:922
 #5  0x00007ff31d881de5 in options_act (old_options=0x7ff308105910)
     at ../src/or/config.c:1396
 #6  set_options (new_val=new_val at entry=0x7ff314032e40,
     msg=msg at entry=0x7fff49cba148) at ../src/or/config.c:596
 #7  0x00007ff31d88360d in options_trial_assign (list=0x7ff314032570,
     use_defaults=use_defaults at entry=0, clear_first=clear_first at entry=1,
     msg=msg at entry=0x7fff49cba148) at ../src/or/config.c:1865
 #8  0x00007ff31d8a042e in control_setconf_helper (
     conn=conn at entry=0x7ff320da7ec0, len=len at entry=3704, body=<optimized
 out>,
     body at entry=0x7ff320cfcbd8 "ORPort=\"9000 IPv4Only\" ORPort=\"9001
 IPv4Only\" ORPort=\"9002 IPv4Only\" ORPort=\"9003 IPv4Only\" ORPort=\"9004
 IPv4Only\" ORPort=\"9005 IPv4Only\" ORPort=\"9006 IPv4Only\" ORPort=\"9007
 IPv4Only\" ORPort=\"9008 IPv"..., use_defaults=0) at
 ../src/or/control.c:762
 #9  0x00007ff31d8a3a25 in handle_control_resetconf (body=<optimized out>,
     len=<optimized out>, conn=<optimized out>) at ../src/or/control.c:809
 #10 connection_control_process_inbuf (conn=conn at entry=0x7ff320da7ec0)
     at ../src/or/control.c:3419
 #11 0x00007ff31d8874a9 in connection_process_inbuf (
     conn=conn at entry=0x7ff320da7ec0,
 package_partial=package_partial at entry=1)
     at ../src/or/connection.c:4011
 #12 0x00007ff31d88d6dd in connection_handle_read_impl
 (conn=0x7ff320da7ec0)
     at ../src/or/connection.c:2839
 #13 connection_handle_read (conn=conn at entry=0x7ff320da7ec0)
     at ../src/or/connection.c:2880
 #14 0x00007ff31d7e9061 in conn_read_callback (fd=<optimized out>,
     event=<optimized out>, _conn=0x7ff320da7ec0) at ../src/or/main.c:718
 #15 0x00007ff31cee1ccc in event_base_loop ()
    from /usr/lib/x86_64-linux-gnu/libevent-2.0.so.5
 #16 0x00007ff31d7e99f5 in do_main_loop () at ../src/or/main.c:1992
 #17 0x00007ff31d7eb1de in tor_main (argc=7, argv=0x7fff49cba648)
     at ../src/or/main.c:2708
 #18 0x00007ff31c55fead in __libc_start_main (main=<optimized out>,
     argc=<optimized out>, ubp_av=<optimized out>, init=<optimized out>,
     fini=<optimized out>, rtld_fini=<optimized out>,
 stack_end=0x7fff49cba638)
     at libc-start.c:228
 #19 0x00007ff31d7e5a9d in _start ()
 }}}

 So Tor is stuck trying to write a log message to file descriptor 1, which
 is a pipe, the other end of which is connected to the controller process,
 because STEM parses notice-level log output to know when the Tor process
 is fully spun up.  (Tor's stderr is also a pipe connected to STEM.)  But
 STEM is blocked reading from the control socket, and in general doesn't
 appear to bother reading from *either* its stdout or stderr pipes after
 `stem.process.launch_tor` returns.  I guess the pipe just happens to fill
 up at 160 open ORPorts.  I can work around this in my code but I think it
 still qualifies as a bug in STEM.

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