No download at all, both in 0.4.2 and 0.4.4: no download at all with two NZbs in

[sander]

(trying to get this posted. Sorry if it shows up twice or even more)

Strange behavior, both in 0.4.2 and 0.4.4: no download at all with two NZbs in the queue. Restarting SAB does not change anything.

I've two NZBs in the queue, one small one and a big one.
Connections shows the 4 active newsservers, each with message-IDs SAB is trying to fetch, BUT all connection counters are on 0.

SAB stays on:

Status: Idle
Speed: 0 kB/s
Queue: 5061.53/5061.53

Changing the order of the queue does not change anything.

The stdout / stderr of SAB shows

2008-09-28 12:10:32,931::INFO::[downloader] [email protected]:119: Initiating connection
2008-09-28 12:10:33,283::INFO::[downloader] [email protected]:119: Initiating connection
2008-09-28 12:10:33,614::INFO::[downloader] [email protected]:119: Initiating connection
2008-09-28 12:10:33,964::INFO::[downloader] [email protected]:119: Initiating connection
2008-09-28 12:10:34,110::INFO::[downloader] [email protected]:119: Initiating connection
2008-09-28 12:10:34,226::INFO::[downloader] [email protected]:119: Initiating connection
2008-09-28 12:10:34,342::INFO::[downloader] [email protected]:563: Initiating connection
2008-09-28 12:10:34,517::INFO::[downloader] [email protected]:563: Initiating connection
2008-09-28 12:10:34,680::INFO::[downloader] [email protected]:563: Initiating connection
2008-09-28 12:10:34,848::INFO::[downloader] [email protected]:119: Initiating connection

and then only WebGUI interaction.

Disk space is 12+ GB, system is Ubuntu 8.04 64-bit.

Any tips ...... ?

[sander]

Here's the proof that NNTP connectivity is just fine: a manual NNTP session to one of the newsservers:

Code: Select all

sander@ubuntu804:~$ telnet news.ipv6.eweka.nl nntp
Trying 2001:4de0:1::1:1...
Connected to news.ipv6.eweka.nl.
Escape character is '^]'.
201 news.ipv6.eweka.nl NNRP Service Ready - [email protected] (no posting).
quit
205 Transferred 73 bytes in 0 articles, 0 groups.  Disconnecting.
Connection closed by foreign host.
sander@ubuntu804:~$

[sander]

And more stderr / stdout


2008-09-28 12:45:48,622::WARNING::[downloader] Thread [email protected]:119: failed to initialize
2008-09-28 12:45:48,623::WARNING::[downloader] Thread [email protected]:119: timed out
2008-09-28 12:45:48,623::WARNING::[downloader] Thread [email protected]:119: timed out
2008-09-28 12:45:48,625::WARNING::[downloader] Thread [email protected]:119: timed out
2008-09-28 12:45:48,626::WARNING::[downloader] Thread [email protected]:119: timed out
2008-09-28 12:45:48,626::WARNING::[downloader] Thread [email protected]:119: timed out
2008-09-28 12:45:48,627::WARNING::[downloader] Thread [email protected]:119: timed out
2008-09-28 12:45:48,628::WARNING::[downloader] Thread [email protected]:119: timed out
2008-09-28 12:45:48,628::WARNING::[downloader] Thread [email protected]:119: timed out
2008-09-28 12:45:48,629::WARNING::[downloader] Thread [email protected]:119: timed out
2008-09-28 12:45:48,629::WARNING::[downloader] Thread [email protected]:563: timed out
2008-09-28 12:45:48,630::WARNING::[downloader] Thread [email protected]:563: timed out
2008-09-28 12:45:48,631::WARNING::[downloader] Thread [email protected]:563: timed out


Strange ...

[shypike]

I have just downloaded stuff from ipv6.xsnews.nl with 0.4.4, no problems here.

Reboot system? Clean the queue?
Checked the start of the log file for suspicious reports?

[sander]

I reboot(ed) the system and did not activate IPv6 and restarted SAB: still nothing.

I stopped SAB under my own account, and logged on to another account, upgraded the 0.3.4 tot 0.4.4, started SAB, put one NZB in the queue, and ... it worked!

So difference with my own account: other account, only one newsserver defined, probably cleaner sabnzbd.ini. But: on the same system, same OS, same connection.

So root cause still not found. Gut feeling: SAB doesn't like a lot of newsservers, so I'll remove them and see what happens.

[sander]

Yep: my gut feeling was correct: after removing all-but-one newsserver, SAB is happily downloading again.

Status: Downloading
Speed: 1259 kB/s
Queue: 5024.12/5061.53

I've experienced this behavior before ... :-(

Any way to handle / analyze this systematically?

[sander]

FWIW: the diff between the functional sabnzbd.ini and the nonfunctional sabnzbd.ini, with all "password" and "username" lines removed:

Code: Select all

sander@ubuntu804:~/.sabnzbd$ diff sabnzbd.ini sabnzbd.ini.2009-09-28---no-download | egrep -vi -e password -e username
70a71,88
> [[newszilla6.xs4all.nl:119]]
> host = newszilla6.xs4all.nl
> port = 119
> connections = 0
> timeout = 120
> fillserver = 1
> ssl = 0
> [[news.ipv6.eweka.nl:119]]
> host = news.ipv6.eweka.nl
> port = 119
> connections = 6
> timeout = 120
> fillserver = 0
> ssl = 0
79a98,115
> [[sslreader.eweka.nl:563]]
> host = sslreader.eweka.nl
> port = 563
> connections = 3
> timeout = 120
> fillserver = 0
> ssl = 1
> [[reader.ipv6.xsnews.nl:119]]
> host = reader.ipv6.xsnews.nl
> port = 119
> connections = 3
> timeout = 120
> fillserver = 0
> ssl = 1
sander@ubuntu804:~/.sabnzbd$

I don't see anything special. Just servers removed (via the WebGUI).

[sander]

Checked the start of the log file for suspicious reports?

I did check the stderr / stdlog (and mailed it to bugs@), and found nothing special.

[jcfp]

Have been seeing this problem too last week, it is caused by some server that is malfunctioning, resulting in sabnzbd doing nothing but wait (and subsequently timeout after 120s) on all servers. The problem was gone once I disabled the xsnews ipv6 server, with downloads on the remaining servers (1 x ipv4+ssl, 2 x ipv6) working just fine. A few days ago when I first noticed this problem again, any attempt to connect to xsnews via ipv6 resulted in it slowly timing out, as if it were firewalled; currently, a tcp connection can be established and kept open but the server doesn't send any data whatsoever (not even the nntp 201 greeting thing). Both of these result in the same behaviour I described above.

I do remember discussing this issue before somewhere?

[sander]

I do remember discussing this issue before somewhere?

Could be very well! Must be the same as my gut feeling. ;-)

What I remember from the past: if one server is down, the complete download will go down to almost-zero speed.

But, AFAIK, there's still no solution nor work around nor root cause analysis.

Well, there is a work around: only have one server defined. ;-(

[jcfp]

The workaround is simple: just set the number of connections on the offending server to zero, and downloading will work fine on the remaining servers. Or at least, it does here

And the server being down is not necessarily an issue, i.e. if sabnzbd get a clear, immediate "connection refused" or "wrong password" error there's no problem or only a slight penalty in the download speed. The problem only shows when some server times out slowly or doesn't respond; this somehow causes the program to not download anything at all (as your topic title already states) - not even from working servers. The problem server times out after some time (120 seconds) but so do all the others; this process then appears to repeat indefinitely.

[sander]

Would it be helpful if I use wireshark / ethereal (or tcpdump) to see what network communication is going on when SAB is not successfully downloading? That way I could see whether SAB tries to communicate with the functional servers at all and whether output is coming back.

Or should I use a "python tracer", like the pythontracer on http://code.google.com/p/pythontracer/

[Jere_Tristan]

Did you not get "trying to connect from multiple IP addresses" warnings?

[sander]

Did you not get "trying to connect from multiple IP addresses" warnings?

No, I didn't.

[sander]

tcpdump is showing that SABnzbd is only trying to set up a connection to the non-functional servertest.news-service.com , does not get a reply from that server, and does not set up connections to the other defined server (news.ipv6.eweka.nl)... :-(

Code: Select all

sander@fujitsu:~$ cat tcpdump.sab.txt  | grep -vi STP | grep -vi arp
23:57:06.365703 IP fujitsu.local.57190 > ns3.tiscali.nl.domain: 59261+ A? test.news-service.com. (39)
23:57:06.393498 IP ns3.tiscali.nl.domain > fujitsu.local.57190: 59261 1/3/1 A[|domain]
23:57:06.393631 IP fujitsu.local.40367 > test.news-service.com.nntps: S 3627985186:3627985186(0) win 5840 <sackOK,timestamp 842078 0,mss 1460,nop,wscale 6>
23:57:09.390503 IP fujitsu.local.40367 > test.news-service.com.nntps: S 3627985186:3627985186(0) win 5840 <sackOK,timestamp 842828 0,mss 1460,nop,wscale 6>
23:57:15.390446 IP fujitsu.local.40367 > test.news-service.com.nntps: S 3627985186:3627985186(0) win 5840 <sackOK,timestamp 844328 0,mss 1460,nop,wscale 6>
23:57:27.390440 IP fujitsu.local.40367 > test.news-service.com.nntps: S 3627985186:3627985186(0) win 5840 <sackOK,timestamp 847328 0,mss 1460,nop,wscale 6>
23:57:51.390456 IP fujitsu.local.40367 > test.news-service.com.nntps: S 3627985186:3627985186(0) win 5840 <sackOK,timestamp 853328 0,mss 1460,nop,wscale 6>

Output of SAB itself:

Code: Select all

2008-10-04 23:57:06,106::ERROR::[newswrapper] Failed to connect: timed out [email protected]:563                                                                                               
2008-10-04 23:57:06,107::ERROR::[downloader] Failed to initialize [email protected]:563                                                                                                        
2008-10-04 23:57:06,107::WARNING::[downloader] Thread [email protected]:563: failed to initialize                                                                                              
2008-10-04 23:57:06,108::INFO::[downloader] [email protected]:563: Initiating connection                                                                                                       
2008-10-04 23:59:06,394::ERROR::[newswrapper] Failed to connect: timed out [email protected]:563                                                                                               
2008-10-04 23:59:06,395::ERROR::[downloader] Failed to initialize [email protected]:563                                                                                                        
2008-10-04 23:59:06,396::WARNING::[downloader] Thread [email protected]:563: failed to initialize
2008-10-04 23:59:06,396::INFO::[downloader] [email protected]:563: Initiating connection

SAB is completely ignoring the other, functional server in sabnzbd.ini. That's causing the block.

FWIW: I swapped the two servers in sabnzbd.ini just to check whether order in the ini mattered, but it doesn't: the other server is still ignored.