Long pause before download starts

[alanspa]

Hi,
I recently installed SAB 1.0.0 on Debian (Wheezy) and noticed that when connecting to astraweb there is a 15 second pause between establishing each connection. It is very similar to the problem as detailed here:
https://forums.sabnzbd.org/viewtopic.php?t=19607. That post has a reply that it is fixed in v0.8.0 beta 2, but I am experiencing the problem in v1.0.0.

My sabnzbd.log looks like this:
2016-03-31 09:33:48,532::INFO::[downloader:444] [email protected]: Initiating connection
2016-03-31 09:34:05,084::INFO::[happyeyeballs:111] Quickest IP address for ssl.astraweb.com (port 443, ssl True, preferipv6 True) is 216.151.153.47
2016-03-31 09:34:05,086::INFO::[downloader:444] [email protected]: Initiating connection
2016-03-31 09:34:21,627::INFO::[happyeyeballs:111] Quickest IP address for ssl.astraweb.com (port 443, ssl True, preferipv6 True) is 216.151.153.12
2016-03-31 09:34:21,628::INFO::[downloader:444] [email protected]: Initiating connection
2016-03-31 09:34:37,986::INFO::[happyeyeballs:111] Quickest IP address for ssl.astraweb.com (port 443, ssl True, preferipv6 True) is 207.246.207.130
2016-03-31 09:34:37,987::INFO::[downloader:444] [email protected]: Initiating connection
2016-03-31 09:34:54,341::INFO::[happyeyeballs:111] Quickest IP address for ssl.astraweb.com (port 443, ssl True, preferipv6 True) is 216.151.153.47
2016-03-31 09:34:54,342::INFO::[downloader:444] [email protected]: Initiating connection
2016-03-31 09:35:10,733::INFO::[happyeyeballs:111] Quickest IP address for ssl.astraweb.com (port 443, ssl True, preferipv6 True) is 207.246.207.129
2016-03-31 09:35:10,733::INFO::[downloader:444] [email protected]: Initiating connection
2016-03-31 09:35:27,096::INFO::[happyeyeballs:111] Quickest IP address for ssl.astraweb.com (port 443, ssl True, preferipv6 True) is 207.246.207.131
2016-03-31 09:35:27,096::INFO::[downloader:444] [email protected]: Initiating connection

Anyone else experiencing this? Any workaround/fix?

Thanks

[sander]

Can you set Logging to +Debug, and then re-run and post the logging? The DEBUG will tell how long the happy-eyeballs-connect takes. Normally it takes a few microseconds (see below).

Can you also add newszilla.xs4all.nl as newsserver (with no account) as a reference?

Code: Select all

2016-03-02 09:12:00,276::DEBUG::[happyeyeballs:113] Happy Eyeballs lookup took 3.924 microseconds
2016-03-02 09:16:01,631::DEBUG::[happyeyeballs:113] Happy Eyeballs lookup took 3.23 microseconds
2016-03-02 09:20:06,192::DEBUG::[happyeyeballs:113] Happy Eyeballs lookup took 5.11 microseconds
2016-03-02 09:24:07,754::DEBUG::[happyeyeballs:113] Happy Eyeballs lookup took 3.782 microseconds
2016-03-02 09:28:09,300::DEBUG::[happyeyeballs:113] Happy Eyeballs lookup took 3.656 microseconds
2016-03-04 13:57:03,954::DEBUG::[happyeyeballs:113] Happy Eyeballs lookup took 12.548 microseconds
2016-03-04 13:57:04,003::DEBUG::[happyeyeballs:113] Happy Eyeballs lookup took 3.034 microseconds
2016-03-04 13:57:04,027::DEBUG::[happyeyeballs:113] Happy Eyeballs lookup took 2.95899999999 microseconds
2016-03-04 13:57:04,045::DEBUG::[happyeyeballs:113] Happy Eyeballs lookup took 2.449 microseconds

Code: Select all

2016-03-04 13:57:04,029::INFO::[downloader:444] [email protected]: Initiating connection
2016-03-04 13:57:04,045::INFO::[happyeyeballs:111] Quickest IP address for newszilla.xs4all.nl (port 119, ssl 0, preferipv6 True) is 2001:888:0:18::119
2016-03-04 13:57:04,045::DEBUG::[happyeyeballs:113] Happy Eyeballs lookup took 2.449 microseconds
2016-03-04 13:57:04,045::DEBUG::[downloader:121] For server newszilla.xs4all.nl, using IP 2001:888:0:18::119 as server

Code: Select all

2016-03-02 09:28:09,087::INFO::[downloader:444] [email protected]: Initiating connection
2016-03-02 09:28:09,300::INFO::[happyeyeballs:111] Quickest IP address for ssl-news.eu.xlusenet.nl (port 119, ssl 0, preferipv6 True) is 2001:4de0:1::234
2016-03-02 09:28:09,300::DEBUG::[happyeyeballs:113] Happy Eyeballs lookup took 3.656 microseconds
2016-03-02 09:28:09,301::DEBUG::[downloader:121] For server ssl-news.eu.xlusenet.nl, using IP 2001:4de0:1::234 as server

And astraweb (for which I have no account):

Code: Select all

2016-03-31 13:39:26,284::INFO::[downloader:444] [email protected]: Initiating connection
2016-03-31 13:39:26,927::INFO::[happyeyeballs:111] Quickest IP address for ssl.astraweb.com (port 563, ssl True, preferipv6 True) is 207.246.207.130
2016-03-31 13:39:26,928::DEBUG::[happyeyeballs:113] Happy Eyeballs lookup took 119.023 microseconds
2016-03-31 13:39:26,928::DEBUG::[downloader:121] For server ssl.astraweb.com, using IP 207.246.207.130 as server

2016-03-31 13:39:26,929::INFO::[downloader:444] [email protected]: Initiating connection
2016-03-31 13:39:27,565::INFO::[happyeyeballs:111] Quickest IP address for ssl.astraweb.com (port 563, ssl True, preferipv6 True) is 8.17.249.103
2016-03-31 13:39:27,565::DEBUG::[happyeyeballs:113] Happy Eyeballs lookup took 41.213 microseconds
2016-03-31 13:39:27,565::DEBUG::[downloader:121] For server ssl.astraweb.com, using IP 8.17.249.103 as server

2016-03-31 13:39:27,566::INFO::[downloader:444] [email protected]: Initiating connection
2016-03-31 13:39:28,230::INFO::[happyeyeballs:111] Quickest IP address for ssl.astraweb.com (port 563, ssl True, preferipv6 True) is 207.246.207.125
2016-03-31 13:39:28,230::DEBUG::[happyeyeballs:113] Happy Eyeballs lookup took 29.42 microseconds
2016-03-31 13:39:28,230::DEBUG::[downloader:121] For server ssl.astraweb.com, using IP 207.246.207.125 as server

Astraweb port 443:

Code: Select all

2016-03-31 13:41:44,802::INFO::[downloader:444] [email protected]: Initiating connection
2016-03-31 13:41:45,439::INFO::[happyeyeballs:111] Quickest IP address for ssl.astraweb.com (port 443, ssl True, preferipv6 True) is 207.246.207.12
2016-03-31 13:41:45,439::DEBUG::[happyeyeballs:113] Happy Eyeballs lookup took 116.401 microseconds
2016-03-31 13:41:45,440::DEBUG::[downloader:121] For server ssl.astraweb.com, using IP 207.246.207.12 as server
2016-03-31 13:41:45,444::INFO::[downloader:444] [email protected]: Initiating connection
2016-03-31 13:41:46,086::INFO::[happyeyeballs:111] Quickest IP address for ssl.astraweb.com (port 443, ssl True, preferipv6 True) is 207.246.207.129
2016-03-31 13:41:46,086::DEBUG::[happyeyeballs:113] Happy Eyeballs lookup took 116.904 microseconds
2016-03-31 13:41:46,087::DEBUG::[downloader:121] For server ssl.astraweb.com, using IP 207.246.207.129 as server
2016-03-31 13:41:46,088::INFO::[downloader:444] [email protected]: Initiating connection
2016-03-31 13:41:46,734::INFO::[happyeyeballs:111] Quickest IP address for ssl.astraweb.com (port 443, ssl True, preferipv6 True) is 207.246.207.129
2016-03-31 13:41:46,734::DEBUG::[happyeyeballs:113] Happy Eyeballs lookup took 39.304 microseconds
2016-03-31 13:41:46,734::DEBUG::[downloader:121] For server ssl.astraweb.com, using IP 207.246.207.129 as server
2016-03-31 13:41:46,738::INFO::[downloader:444] [email protected]: Initiating connection
2016-03-31 13:41:47,218::INFO::[happyeyeballs:111] Quickest IP address for ssl.astraweb.com (port 443, ssl True, preferipv6 True) is 207.246.207.130
2016-03-31 13:41:47,218::DEBUG::[happyeyeballs:113] Happy Eyeballs lookup took 114.163 microseconds
2016-03-31 13:41:47,218::DEBUG::[downloader:121] For server ssl.astraweb.com, using IP 207.246.207.130 as server

[alanspa]

Thanks for the advice. I enabled debugging, and checked the logs again. Then thinking of the process and what is happening at that stage of the download (lookups), I checked my DNS server config on the machine. I was using an old DNS server as primary (which may not exist anymore), and Google's DNS as secondary. What was probably happening is that the lookup was timing out on the primary DNS, and resolving using the secondary DNS.

I have changed the DNS to only use Google's DNS and it is now in microsecond range (~30 microseconds) which is not as fast as yours listed, but is a lot faster than what I was getting.

[sander]

Cool that it now works for you! Thanks for reporting back.