Cause of connection timeout issues found (and solved in Beta6)

[shypike]

I finally managed to find out why some people complain about intermittent
and sometimes frequent timeouts on their server connections.

It turns out that on some systems for some Usenet providers, DNS resolving takes very long.
On Linux systems it's seems worse than on Windows.
It's probably a combination of the OS and the network library we use.

The download section is designed under the assumption that DNS resolving takes a few seconds.
If it starts taking between 10 and 30 seconds, already established sessions will time out.
This is especially true for unresolvable addresses (like those of free IPV6 servers that are often off-line).

Anyway, discovery is 50% of the solution.
It will take a few days to work out (and test) a proper work-around for this.

EDIT: Solved in Beta6.

As soon as it's ready there will be a new Beta.

[switch]

Great news, good work shypike.

[JWV]

I doubt whether DNS is the cause.
I changed my server from hostname to its IP address, eliminating DNS lookups.
The problems still occurs.

Furthermore: for me this is not a BETA only issue, it occurred also in 0.4.12 and started a few days ago (Ubuntu 9.10 / XBMC Live 9.11).

To give an impression of the speed of my downloads (8 mbit line), this is the output of 'ífstat' (every line is a second):

Code: Select all

       eth0
 KB/s in  KB/s out
  734.84     23.89
  761.87     25.23
  766.87     31.14
  270.23     10.79
  432.73     15.98
  665.27     19.39
  759.89     21.70
  712.06     22.97
  633.57     22.52
  632.63     21.26
  783.12     26.75
  374.46     11.86
  317.19     13.81
  178.16      6.85
  514.53     19.79
  393.79     10.96
  449.03     14.28
  461.72     18.87
  560.04     17.14
  531.72     15.40
  660.93     19.15
       eth0
 KB/s in  KB/s out
  672.10     22.15
  640.61     28.05
  350.84     12.66
  789.33     30.26
  620.30     19.77
  417.95     11.92
   14.59      3.27
    0.23      0.12
    0.06      0.12
    0.06      0.12
    0.06      0.12
    0.65      1.94
    2.07      0.88
    0.06      0.12
    0.12      0.19
    0.06      0.12
    0.12      0.19
    2.65      2.70
    0.06      0.12
    0.12      0.12
    0.06      0.12
       eth0
 KB/s in  KB/s out
    0.06      0.12
    2.65      2.73
    0.06      0.12
    0.06      0.12
    0.06      0.12
    0.06      0.12
    2.65      2.70
    0.06      0.12
    0.06      0.12
    0.06      0.12
    0.06      0.12
    2.65      2.70
    0.06      0.12
    0.06      0.12
    0.06      0.12
    0.88      0.62
    2.65      2.61
    0.06      0.12
    0.06      0.12
    0.06      0.12
    0.06      0.12
       eth0
 KB/s in  KB/s out
    2.65      2.61
    0.30      0.15
    0.06      0.12
    0.06      0.12
    0.06      0.12
    2.65      2.61
    0.06      0.12
    0.06      0.12
    0.06      0.12
    0.06      0.12
    2.65      2.61
    0.06      0.12
    0.06      0.12
    0.06      0.12
    0.06      0.12
    2.65      2.61
    0.06      0.12
    0.06      0.12
    0.12      0.19
    0.06      0.12
    2.65      2.60
       eth0
 KB/s in  KB/s out
    0.06      0.12
    3.01      0.28
    0.06      0.12
  241.77      6.19
  811.88     30.25
  598.82     20.26
  478.51     14.73
  537.83     20.94
  395.84     13.96
  610.37     21.56

And this is a snip of the logging (0.5.0 beta 5):

Code: Select all

2010-01-07 21:19:25,457::DEBUG::[bpsmeter:59] bps: 492732.7832
2010-01-07 21:19:30,463::DEBUG::[bpsmeter:59] bps: 197809.73782
2010-01-07 21:19:35,474::DEBUG::[bpsmeter:59] bps: 79351.2903414
2010-01-07 21:19:40,480::DEBUG::[bpsmeter:59] bps: 31856.5551993
2010-01-07 21:19:45,487::DEBUG::[bpsmeter:59] bps: 12789.2165333
2010-01-07 21:19:50,493::DEBUG::[bpsmeter:59] bps: 5134.38377541
2010-01-07 21:19:54,498::WARNING::[downloader:673] Thread [email protected]:119: timed out
2010-01-07 21:19:54,600::WARNING::[downloader:673] Thread [email protected]:119: timed out
2010-01-07 21:19:54,702::WARNING::[downloader:673] Thread [email protected]:119: timed out
2010-01-07 21:20:24,840::INFO::[downloader:437] [email protected]:119: Initiating connection
2010-01-07 21:20:24,871::INFO::[downloader:437] [email protected]:119: Initiating connection
2010-01-07 21:20:24,893::INFO::[downloader:437] [email protected]:119: Initiating connection

My timeout is set to 30 (it wont go lower), it seems that after every thread the connection times out and then waits 30 seconds and then continues..

Any clue?

[zerojay]

I'm seeing the same type of issue, same sort of logs and it all started a few days ago as well. Y2K10 bug, guys?

[shypike]

It isn't DNS as such, but a combination of Python's network library, the OS and the specific server.
The design did not take into account long resolution times.
It gets really bad when an address doesn't resolve at all.
Also, non-responding servers create problems.

Anyway, we have it covered now and a new Beta is on the way.

[JWV]

Thanks for the fix!
Just verified beta6, downloading is steady now! 

[TuffScout]

Today 14-01-2010 (14:30 GMT), is the DNS problem solved? and can we go with the fixed beta6 version?

Thanks for the reply.

[shypike]

Today 14-01-2010 (14:30 GMT), is the DNS problem solved? and can we go with the fixed beta6 version?

Thanks for the reply.

There is no DNS problem.
Only the TestServer buttons in the Wizard and Config->Servers are broken.
Entering new servers and actual downloading works fine.