Many new connections per second [was Re: URGENT: patch needed ASAP for authority bug]

[Hans Schnehl]

On Thu, Apr 15, 2010 at 02:30:14PM -0400, Roger Dingledine wrote:
> On Thu, Apr 15, 2010 at 09:13:16AM -0400, Roger Dingledine wrote:
> > But that said, there does seem to be a problem here: we're seeing way
> > more directory requests than we were a few weeks ago. That's translating
> > into more connections seen by relays.
> > 
> > Is that because we're seeing way more users? Or are Tor clients generating
> > more directory requests than they "should"? Hm.
> 
> moria1 is seeing >1000 flows per second.
> 
> See also
> https://bugs.torproject.org/flyspray/index.php?do=details&id=1356
> 
> I'm going to take a closer look at it later tonight, and see if I can make
> some guesses about what's up -- that is, what changed in the past week.
> 
> Let us know if you find any hints. :)

Hi,

The node vallenator is (was) capable and running with around 20 - 23 mbit/s
for long w/o serious trouble until the mess started a few days ago.  To make
it short, on  FBSD 8.- Stable I tried different versions od tor-0.2.2.10-alpha-dev
and Tor  v0.2.1.25 compiled against different versions of libevent 2-dev and
libevent 1.4.13 , but all with openssl-1.0.0 or openssl-1.0.0beta4 to beta5.

Within a relatively short time (~ two hours) a very large number of simultaneous
connections build up with all .  Max was 20000 with a throughput of around 7
mbit/s. This also  is the upper limit of states this system will accept and
is more than enough under normal circumstances, meaning the under normal
conditions  utilized bandwidth.

All setups  showed the same message in the logs:  (sorry for linebreaks) 
Apr 14 16:28:16.035 [info]   
onion_pending_add(): Circuit create request is too old; canceling due to
overload.  
(src/or/onion.c)
There were about 3000 of those messages per hour.

I tried a client with some of these combinations, it actually worked and had
no warnings in the logs, it only was a little slower than usual. Wonder what
this client told the servers it tried to connect to.  It appeared as if a
mere client does not necessarily make notice of something going wrong, it
works simply a little to much slower as usual, for many users not very unusual.

During Bootstrapping there werde complaints about 'unknown authorities'...
legacy...'.

With tor-0.2.2.10-alpha-dev openssl-1.0.0beta4 and libevent 1.4.13,which
worked rather stable at around 15mbit ciphers were completely borked.
[warn] No ciphers on session 
(from src/common/tortls.c) also thousands.

Due to all this 'testing'  the node lost it's Guard and Stable flags and is
running now as tor-0.2.2.10-alpha-dev (I believe just one commit before
--11.alpha-dev) with libevent -dev as of today and  OpenSSL 0.9.8n.  If there
was something like an AvoidMostBumpyMiddleman flag, the node  has qualified 
during the last days.

There are, after some 6 hours uptime, some 12500 stateful connections and
relays traffic at ~5mbit.  The number  connections is  still increasing, but
a lot slower than with earlier Tors, and throughput decreasing.

OK -> was about to send this and took a last look at the node, here we go:

oma at vallenator# grep overload /usr/local/etc/tor/debug.log | head -1 
Apr 15 20:19:27.070 [info] onion_pending_add(): Circuit create request is
too old; canceling due to overload.

oma at vallenator# grep overload /usr/local/etc/tor/debug.log | tail -1 
Apr 15 20:35:58.598 [info] onion_pending_add(): Circuit create request is
too old; canceling due to overload.

oma at vallenator# grep overload /usr/local/etc/tor/debug.log | wc -l
    3830

so its 3830 'warn... overload'  in ~15 minutes... new record ;)

seems to even grow: 
oma at vallenator# grep overload /usr/local/etc/tor/debug.log \
| wc -l && date
    5745
Thu Apr 15 20:44:02 UTC 2010

wow.

The Number of states stays at around 12700 and throughput drops to ~3 mbit.

Last one:
oma at vallenator# grep overload /usr/local/etc/tor/debug.log | wc -l && date
    9966
Thu Apr 15 21:03:40 UTC 2010

HTH

Hans