0.7.0beta3 issue: connection drops and "missing" articles

[Silverlock]

The short story:

On either Ubuntu 10.10 or 11.04, 0.7.0 beta3 won't communicate reliably with my news server. The symptoms are highly erratic transfer rates, more often than not going right to zero for a minute or two, claims of boatloads of missing articles (that are really there) and constant disconnects.

0.5.6 and 0.6.15 work perfectly, as does nzb 0.2 and Xnews running under wine.


The longer story:

I recently upgraded a system from 10.10 to 11.04. After the upgrade I noticed that my 0.6.15 sabnzbd installation had been downgraded to 0.5.6. No problem, I just re-enabled the jcfp repository and got the brand spanking new 0.7.0 beta3. As soon as I fed an nzb file to the upgrade the problems started. My previously rock steady 600KB/s transfer rate was bouncing all over the place. The log file indicated masses of connection drops and missing articles. When a download completed at all (and most didn't due to 'missing' articles), it took many times longer than it had previously.

I tried putting a speed limit on the transfers. That helped sometimes. The daemon would purr along at the reduced rate for several minutes, but would eventually start dropping out again. But more often than not it would never find whatever sweet spot it was looking for and would just continue thrashing.

I un-installed everything, blew away the data files and tried again. No difference.

I tried an installation on another 11.04 box. Same problems.

Thinking it might be something different in 11.04, I tried it on a 10.10 box. Same problems there.

I tried reducing the number of connections. Even reducing it to 1 connection didn't change anything.

I installed nzb and tried that. Worked like a charm. So did Xnews running under wine.

Finally I disabled the jcfp repository and installed the default 0.5.6 version from the natty repository. Success. Everything was back to normal.

I dug up a set of debs for 0.6.15 and installed that. Success with that as well.


There was no information in the log file that indicated any problems beyond the dropped connections and claims of missing articles.

I've looked through the forums and haven't seen anything resembling this issue. So either I'm the only person running sabnzbd under Ubuntu (which I doubt!) or something changed between 0.6.15 and 0.7.0 that started creating issues with my ISP's news server. If it matters, they actually farm their usenet service out to highwinds-media.com.

Does anyone have any suggestions on where I might start looking to solve this problem? Is there some extra hidden debugging stuff I can turn out that might shed some light on what's going on?

[jcfp]

With 0.7, does the server respond with actual errors saying the article doesn't exist (the error code for that is 430 iirc) or is it just timing out? Visible in debug logging.

Could you try with another server, for example with a free trial on some paid usenet provider and see if the problem persists? Preferably some non-highwinds server. Asking because of this thread (in dutch, unfortunately for you), which seems to describe a somewhat similar issue.

[Silverlock]

There was an actual error message about the article being missing, not just a timeout. It said something to the effect that the article was missing from all servers. I can fire up one of the other machines with 0.7 when I get home tonight and get you the exact error message if it'll help. One good thing about this issue is that I have absolutely no problem making it happen!

Trying a different server was actually on my list of things to try before I saw that nzb wasn't having any problems. Up til that point I wasn't 100% sure that the timing wasn't coincidental and that my ISP wasn't the one having the issue. I can still give that a try if need be. Given how things have turned out to this point, I strongly suspect that it'll work and that the problem is something that has changed between 0.6.15 and 0.7 that (while otherwise perfectly within spec) the highwinds server doesn't like.

I gave Google translate a shot to see what was going on in that other thread. Some of the error streams look similar, but not identical. The "Initiating connection/finished" logs are something I was seeing when the throughput was bouncing around all over the place. I don't recall seeing the timed out messages, but I can definitely check that tonight. And they weren't getting any missing article logs that I saw.

[shypike]

There is one important difference between 0.6.15 and 0.7.0.
The latter does limited retries, default three.
If you happen to have set a tight time-out and the server is a bit slow to react,
you'll soon exhaust the retries.
Try tweaking server time-out and the retry setting. You can also (partially) disable retries.
See Config->Switches.

[Silverlock]

So here's the sanitized sabnzbd.log file from startup. You can see the constant reconnections and I caught a few of the 'missing' articles error messages.

I hadn't ever changed the server timeout, so that was 120 seconds for both 0.6.15 and 0.7.0. That would seem to be more than adequate, I'd think. I tried up'ing the number of retries from 3 to 10 and saw no change in behaviour or what I was seeing in the log file. Still lots of connection restarting, throughput dropping to 0, and missing articles.

Code: Select all

2012-05-03 17:30:53,997::INFO::[sabnzbdplus:1236] --------------------------------
2012-05-03 17:30:54,018::INFO::[sabnzbdplus:1237] sabnzbdplus-0.7.0Beta3 (rev=9f7b5412da2572f4cbd4b1dcd2224965921f9e80)
2012-05-03 17:30:54,018::INFO::[sabnzbdplus:1249] Platform = posix
2012-05-03 17:30:54,018::INFO::[sabnzbdplus:1250] Python-version = 2.7.1+ (r271:86832, Apr 11 2011, 18:05:24)
[GCC 4.5.2]
2012-05-03 17:30:54,018::INFO::[sabnzbdplus:1251] Arguments = /usr/bin/sabnzbdplus --daemon --config-file /home/user/.sabnzbd/sabnzbd.ini
2012-05-03 17:30:54,048::INFO::[sabnzbdplus:1264] Read INI file /home/user/.sabnzbd/sabnzbd.ini
2012-05-03 17:30:54,188::INFO::[__init__:901] Loading data for bookmarks.sab from /home/user/.sabnzbd/admin/bookmarks.sab
2012-05-03 17:30:54,189::INFO::[__init__:901] Loading data for rss_data.sab from /home/user/.sabnzbd/admin/rss_data.sab
2012-05-03 17:30:54,189::INFO::[__init__:901] Loading data for totals9.sab from /home/user/.sabnzbd/admin/totals9.sab
2012-05-03 17:30:54,190::INFO::[postproc:90] Loading postproc queue
2012-05-03 17:30:54,190::INFO::[__init__:901] Loading data for postproc1.sab from /home/user/.sabnzbd/admin/postproc1.sab
2012-05-03 17:30:54,191::INFO::[__init__:901] Loading data for queue9.sab from /home/user/.sabnzbd/admin/queue9.sab
2012-05-03 17:30:54,192::INFO::[__init__:901] Loading data for watched_data.sab from /home/user/.sabnzbd/admin/watched_data.sab
2012-05-03 17:30:54,209::INFO::[downloader:208] Resuming
2012-05-03 17:30:54,209::INFO::[__init__:311] All processes started
2012-05-03 17:30:54,210::INFO::[sabnzbdplus:333] Web dir is /usr/share/sabnzbdplus/interfaces/smpl
2012-05-03 17:30:54,237::INFO::[sabnzbdplus:333] Web dir is /usr/share/sabnzbdplus/interfaces/Config
2012-05-03 17:30:54,444::INFO::[sabnzbdplus:449] _yenc module... found!
2012-05-03 17:30:54,444::INFO::[sabnzbdplus:457] par2 binary... found (/usr/bin/par2)
2012-05-03 17:30:54,445::INFO::[sabnzbdplus:465] unrar binary... found (/usr/bin/unrar)
2012-05-03 17:30:54,445::INFO::[sabnzbdplus:470] unzip binary... found (/usr/bin/unzip)
2012-05-03 17:30:54,451::INFO::[sabnzbdplus:476] nice binary... found (/usr/bin/nice)
2012-05-03 17:30:54,452::INFO::[sabnzbdplus:480] ionice binary... found (/usr/bin/ionice)
2012-05-03 17:30:54,452::INFO::[sabnzbdplus:485] pyOpenSSL... found (True)
2012-05-03 17:30:54,490::INFO::[sabnzbdplus:1447] Starting web-interface on 0.0.0.0:8080
2012-05-03 17:30:54,491::INFO::[_cplogging:55] [03/May/2012:17:30:54] ENGINE Bus STARTING
2012-05-03 17:30:54,559::INFO::[_cplogging:55] [03/May/2012:17:30:54] ENGINE Started monitor thread '_TimeoutMonitor'.
2012-05-03 17:30:54,800::INFO::[_cplogging:55] [03/May/2012:17:30:54] ENGINE Serving on 0.0.0.0:8080
2012-05-03 17:30:55,014::INFO::[_cplogging:55] [03/May/2012:17:30:55] ENGINE Serving on ::1:8080
2012-05-03 17:30:55,014::INFO::[_cplogging:55] [03/May/2012:17:30:55] ENGINE Bus STARTED
2012-05-03 17:30:55,016::INFO::[notifier:87] Sending registration to localhost:23053
2012-05-03 17:30:55,516::INFO::[sabnzbdplus:1516] Starting sabnzbdplus-0.7.0Beta3
2012-05-03 17:30:55,520::INFO::[dirscanner:269] Dirscanner starting up
2012-05-03 17:30:55,521::INFO::[urlgrabber:76] URLGrabber starting up
2012-05-03 17:36:15,087::INFO::[dirscanner:317] Trying to import /home/user/Downloads/nzb/example.nzb
2012-05-03 17:36:16,112::INFO::[misc:771] Creating directories: /home/user/Downloads/incomplete/example
2012-05-03 17:36:16,141::INFO::[nzbstuff:429] File example.par2 added to queue
2012-05-03 17:36:16,143::INFO::[nzbstuff:429] File example.r00 added to queue
2012-05-03 17:36:16,145::INFO::[nzbstuff:429] File example.r01 added to queue
2012-05-03 17:36:16,147::INFO::[nzbstuff:429] File example.r02 added to queue
2012-05-03 17:36:16,149::INFO::[nzbstuff:429] File example.r03 added to queue
2012-05-03 17:36:16,151::INFO::[nzbstuff:429] File example.r04 added to queue
2012-05-03 17:36:16,153::INFO::[nzbstuff:429] File example.r05 added to queue
2012-05-03 17:36:16,155::INFO::[nzbstuff:429] File example.r06 added to queue
2012-05-03 17:36:16,157::INFO::[nzbstuff:429] File example.r07 added to queue
2012-05-03 17:36:16,158::INFO::[nzbstuff:429] File example.nzb added to queue
2012-05-03 17:36:16,175::INFO::[nzbstuff:429] File example.rar added to queue
2012-05-03 17:36:16,176::INFO::[nzbstuff:429] File example.sfv added to queue
2012-05-03 17:36:16,177::INFO::[nzbstuff:429] File example.srr added to queue
2012-05-03 17:36:16,179::INFO::[nzbstuff:429] File example.vol00+01.par2 added to queue
2012-05-03 17:36:16,180::INFO::[nzbstuff:429] File example.vol01+02.par2 added to queue
2012-05-03 17:36:16,181::INFO::[nzbstuff:429] File example.vol03+04.par2 added to queue
2012-05-03 17:36:16,183::INFO::[nzbstuff:429] File example.vol07+08.par2 added to queue
2012-05-03 17:36:16,185::INFO::[nzbstuff:429] File example.vol15+16.par2 added to queue
2012-05-03 17:36:16,186::INFO::[nzbstuff:429] File example.vol31+03.par2 added to queue
2012-05-03 17:36:16,187::INFO::[__init__:550] Backing up /home/user/Downloads/incomplete/example/__ADMIN__/example.nzb.gz
2012-05-03 17:36:16,195::INFO::[nzbqueue:174] Saving queue
2012-05-03 17:36:16,198::INFO::[__init__:877] Saving data for queue9.sab in /home/user/.sabnzbd/admin/queue9.sab
2012-05-03 17:36:16,199::INFO::[notifier:87] Sending registration to localhost:23053
2012-05-03 17:36:17,701::INFO::[downloader:375] 1@isps.usenet.server:119: Initiating connection
2012-05-03 17:36:17,702::INFO::[downloader:375] 2@isps.usenet.server:119: Initiating connection
2012-05-03 17:36:17,704::INFO::[downloader:375] 3@isps.usenet.server:119: Initiating connection
2012-05-03 17:36:17,705::INFO::[downloader:375] 4@isps.usenet.server:119: Initiating connection
2012-05-03 17:36:17,706::INFO::[downloader:375] 5@isps.usenet.server:119: Initiating connection
2012-05-03 17:36:18,709::INFO::[downloader:563] Connecting 3@isps.usenet.server:119 finished
2012-05-03 17:36:18,709::INFO::[downloader:563] Connecting 4@isps.usenet.server:119 finished
2012-05-03 17:36:18,710::INFO::[downloader:563] Connecting 5@isps.usenet.server:119 finished
2012-05-03 17:36:18,710::INFO::[downloader:563] Connecting 1@isps.usenet.server:119 finished
2012-05-03 17:36:18,710::INFO::[downloader:563] Connecting 2@isps.usenet.server:119 finished
2012-05-03 17:36:19,064::INFO::[__init__:877] Saving data for totals9.sab in /home/user/.sabnzbd/admin/totals9.sab
2012-05-03 17:36:19,064::INFO::[assembler:86] Decoding /home/user/Downloads/incomplete/example/example.par2 yenc
2012-05-03 17:36:19,578::INFO::[downloader:640] Thread 2@isps.usenet.server:119: server closed connection
2012-05-03 17:36:20,201::INFO::[downloader:640] Thread 4@isps.usenet.server:119: server closed connection
2012-05-03 17:36:20,973::INFO::[downloader:640] Thread 5@isps.usenet.server:119: server closed connection
2012-05-03 17:36:21,235::INFO::[downloader:640] Thread 3@isps.usenet.server:119: server closed connection
2012-05-03 17:36:21,350::INFO::[downloader:640] Thread 1@isps.usenet.server:119: server closed connection
2012-05-03 17:36:25,355::INFO::[downloader:375] 2@isps.usenet.server:119: Initiating connection
2012-05-03 17:36:25,356::INFO::[downloader:375] 4@isps.usenet.server:119: Initiating connection
2012-05-03 17:36:26,358::INFO::[downloader:375] 5@isps.usenet.server:119: Initiating connection
2012-05-03 17:36:26,359::INFO::[downloader:375] 3@isps.usenet.server:119: Initiating connection
2012-05-03 17:36:26,360::INFO::[downloader:375] 1@isps.usenet.server:119: Initiating connection
2012-05-03 17:36:26,361::INFO::[downloader:563] Connecting 2@isps.usenet.server:119 finished
2012-05-03 17:36:26,361::INFO::[downloader:563] Connecting 4@isps.usenet.server:119 finished
2012-05-03 17:36:26,552::INFO::[downloader:563] Connecting 5@isps.usenet.server:119 finished
2012-05-03 17:36:26,553::INFO::[downloader:563] Connecting 3@isps.usenet.server:119 finished
2012-05-03 17:36:26,557::INFO::[downloader:563] Connecting 1@isps.usenet.server:119 finished
2012-05-03 17:36:26,739::INFO::[downloader:640] Thread 2@isps.usenet.server:119: server closed connection
2012-05-03 17:36:27,659::INFO::[downloader:640] Thread 4@isps.usenet.server:119: server closed connection
2012-05-03 17:36:27,661::INFO::[downloader:640] Thread 3@isps.usenet.server:119: server closed connection
2012-05-03 17:36:28,280::INFO::[downloader:640] Thread 1@isps.usenet.server:119: server closed connection
2012-05-03 17:36:28,578::INFO::[downloader:640] Thread 5@isps.usenet.server:119: server closed connection
2012-05-03 17:36:32,584::INFO::[downloader:375] 2@isps.usenet.server:119: Initiating connection
2012-05-03 17:36:33,585::INFO::[downloader:375] 4@isps.usenet.server:119: Initiating connection
2012-05-03 17:36:33,586::INFO::[downloader:375] 3@isps.usenet.server:119: Initiating connection
2012-05-03 17:36:33,587::INFO::[downloader:375] 1@isps.usenet.server:119: Initiating connection
2012-05-03 17:36:33,588::INFO::[downloader:375] 5@isps.usenet.server:119: Initiating connection
2012-05-03 17:36:33,589::INFO::[downloader:563] Connecting 2@isps.usenet.server:119 finished
2012-05-03 17:36:33,778::INFO::[downloader:563] Connecting 4@isps.usenet.server:119 finished
2012-05-03 17:36:33,784::INFO::[downloader:563] Connecting 5@isps.usenet.server:119 finished
2012-05-03 17:36:33,785::INFO::[downloader:563] Connecting 1@isps.usenet.server:119 finished
2012-05-03 17:36:33,788::INFO::[downloader:563] Connecting 3@isps.usenet.server:119 finished
2012-05-03 17:36:35,138::INFO::[downloader:640] Thread 3@isps.usenet.server:119: server closed connection
2012-05-03 17:36:35,501::INFO::[downloader:640] Thread 5@isps.usenet.server:119: server closed connection
2012-05-03 17:36:35,610::INFO::[downloader:640] Thread 2@isps.usenet.server:119: server closed connection
2012-05-03 17:36:35,682::INFO::[downloader:640] Thread 4@isps.usenet.server:119: server closed connection
2012-05-03 17:36:36,447::INFO::[downloader:640] Thread 1@isps.usenet.server:119: server closed connection
2012-05-03 17:36:40,452::INFO::[downloader:375] 3@isps.usenet.server:119: Initiating connection
2012-05-03 17:36:41,455::INFO::[downloader:375] 5@isps.usenet.server:119: Initiating connection
2012-05-03 17:36:41,456::INFO::[downloader:375] 2@isps.usenet.server:119: Initiating connection
2012-05-03 17:36:41,457::INFO::[downloader:375] 4@isps.usenet.server:119: Initiating connection
2012-05-03 17:36:41,457::INFO::[downloader:375] 1@isps.usenet.server:119: Initiating connection
2012-05-03 17:36:41,458::INFO::[downloader:563] Connecting 3@isps.usenet.server:119 finished
2012-05-03 17:36:41,664::INFO::[downloader:563] Connecting 1@isps.usenet.server:119 finished
2012-05-03 17:36:41,699::INFO::[downloader:563] Connecting 2@isps.usenet.server:119 finished
2012-05-03 17:36:42,256::INFO::[downloader:563] Connecting 4@isps.usenet.server:119 finished
2012-05-03 17:36:42,392::INFO::[downloader:563] Connecting 5@isps.usenet.server:119 finished
2012-05-03 17:36:42,572::INFO::[downloader:640] Thread 2@isps.usenet.server:119: server closed connection
2012-05-03 17:36:42,573::INFO::[decoder:194] <Article: article=9999999999.99999.1@eu.news.astraweb.com, bytes=787013, partnum=1, art_id=None> => missing from all servers, discarding
2012-05-03 17:36:42,768::INFO::[downloader:640] Thread 4@isps.usenet.server:119: server closed connection
2012-05-03 17:36:42,769::INFO::[decoder:194] <Article: article=9999999999.99999.1@eu.news.astraweb.com, bytes=786802, partnum=1, art_id=None> => missing from all servers, discarding
2012-05-03 17:36:42,969::INFO::[downloader:640] Thread 3@isps.usenet.server:119: server closed connection
2012-05-03 17:36:42,969::INFO::[decoder:194] <Article: article=9999999999.99999.1@eu.news.astraweb.com, bytes=788838, partnum=1, art_id=None> => missing from all servers, discarding
2012-05-03 17:36:43,051::INFO::[downloader:640] Thread 5@isps.usenet.server:119: server closed connection
2012-05-03 17:36:43,051::INFO::[decoder:194] <Article: article=9999999999.99999.1@eu.news.astraweb.com, bytes=786938, partnum=1, art_id=None> => missing from all servers, discarding
2012-05-03 17:36:43,429::INFO::[downloader:640] Thread 1@isps.usenet.server:119: server closed connection
2012-05-03 17:36:43,429::INFO::[decoder:194] <Article: article=9999999999.99999.1@eu.news.astraweb.com, bytes=793037, partnum=1, art_id=None> => missing from all servers, discarding
2012-05-03 17:36:48,436::INFO::[downloader:375] 2@isps.usenet.server:119: Initiating connection
2012-05-03 17:36:48,437::INFO::[downloader:375] 4@isps.usenet.server:119: Initiating connection
2012-05-03 17:36:48,438::INFO::[downloader:375] 3@isps.usenet.server:119: Initiating connection
2012-05-03 17:36:48,439::INFO::[downloader:375] 5@isps.usenet.server:119: Initiating connection
2012-05-03 17:36:48,440::INFO::[downloader:375] 1@isps.usenet.server:119: Initiating connection
2012-05-03 17:36:49,442::INFO::[downloader:563] Connecting 3@isps.usenet.server:119 finished
2012-05-03 17:36:49,443::INFO::[downloader:563] Connecting 5@isps.usenet.server:119 finished
2012-05-03 17:36:49,443::INFO::[downloader:563] Connecting 1@isps.usenet.server:119 finished
2012-05-03 17:36:49,444::INFO::[downloader:563] Connecting 2@isps.usenet.server:119 finished
2012-05-03 17:36:49,444::INFO::[downloader:563] Connecting 4@isps.usenet.server:119 finished
2012-05-03 17:36:49,807::INFO::[downloader:640] Thread 1@isps.usenet.server:119: server closed connection
2012-05-03 17:36:50,619::INFO::[downloader:640] Thread 3@isps.usenet.server:119: server closed connection
2012-05-03 17:36:50,622::INFO::[downloader:640] Thread 5@isps.usenet.server:119: server closed connection
2012-05-03 17:36:50,987::INFO::[downloader:640] Thread 2@isps.usenet.server:119: server closed connection
2012-05-03 17:36:52,226::INFO::[downloader:640] Thread 4@isps.usenet.server:119: server closed connection
2012-05-03 17:36:55,231::INFO::[downloader:375] 1@isps.usenet.server:119: Initiating connection
2012-05-03 17:36:56,233::INFO::[downloader:375] 3@isps.usenet.server:119: Initiating connection
2012-05-03 17:36:56,234::INFO::[downloader:375] 5@isps.usenet.server:119: Initiating connection
2012-05-03 17:36:56,235::INFO::[downloader:375] 2@isps.usenet.server:119: Initiating connection
2012-05-03 17:36:56,236::INFO::[downloader:563] Connecting 1@isps.usenet.server:119 finished
2012-05-03 17:36:56,462::INFO::[downloader:563] Connecting 5@isps.usenet.server:119 finished
2012-05-03 17:36:56,463::INFO::[downloader:563] Connecting 3@isps.usenet.server:119 finished
2012-05-03 17:36:56,465::INFO::[downloader:563] Connecting 2@isps.usenet.server:119 finished
2012-05-03 17:36:57,227::INFO::[downloader:375] 4@isps.usenet.server:119: Initiating connection
2012-05-03 17:36:57,406::INFO::[downloader:563] Connecting 4@isps.usenet.server:119 finished
2012-05-03 17:36:57,437::INFO::[downloader:640] Thread 1@isps.usenet.server:119: server closed connection
2012-05-03 17:36:57,734::INFO::[downloader:640] Thread 3@isps.usenet.server:119: server closed connection
2012-05-03 17:36:59,288::INFO::[downloader:640] Thread 2@isps.usenet.server:119: server closed connection
2012-05-03 17:36:59,516::INFO::[downloader:640] Thread 4@isps.usenet.server:119: server closed connection
2012-05-03 17:37:00,394::INFO::[downloader:640] Thread 5@isps.usenet.server:119: server closed connection
2012-05-03 17:37:03,398::INFO::[downloader:375] 1@isps.usenet.server:119: Initiating connection
2012-05-03 17:37:03,398::INFO::[downloader:375] 3@isps.usenet.server:119: Initiating connection
2012-05-03 17:37:04,400::INFO::[downloader:375] 2@isps.usenet.server:119: Initiating connection
2012-05-03 17:37:04,401::INFO::[downloader:563] Connecting 1@isps.usenet.server:119 finished
2012-05-03 17:37:04,402::INFO::[downloader:563] Connecting 3@isps.usenet.server:119 finished
2012-05-03 17:37:04,554::INFO::[downloader:375] 4@isps.usenet.server:119: Initiating connection
2012-05-03 17:37:04,582::INFO::[downloader:563] Connecting 2@isps.usenet.server:119 finished
2012-05-03 17:37:04,747::INFO::[downloader:563] Connecting 4@isps.usenet.server:119 finished
2012-05-03 17:37:05,119::INFO::[downloader:640] Thread 2@isps.usenet.server:119: server closed connection
2012-05-03 17:37:05,400::INFO::[downloader:375] 5@isps.usenet.server:119: Initiating connection
2012-05-03 17:37:05,451::INFO::[downloader:640] Thread 1@isps.usenet.server:119: server closed connection

[shypike]

I've looked at the changes between 0.6.15 and 0.7.0 that could cause different behaviour.
It's rather limited.
1. Retry limitation (as described in a previous post)
2. Precheck (this has no influence at all when it's off)
3. Closure of all active connections when an optional server is banned for a period
2. Pick random IP when the server name resolves to multiple IP addresses

1. You already tested this, to no avail.
2. Very unlikely cause, definitely when you're not using pre-check
3. Unlikely and if you are not using the "optional" setting, it cannot be a cause at all.

That leaves #4.
Can you check whether your Usenet server has multiple IP addresses.
You should be able to check using "nslookup servername".
Otherwise, start the Python interpreter and type in this mini-program:

Code: Select all

import socket
socket.getaddrinfo("MY_SERVER", 119, 0, socket.SOCK_STREAM)


Replace MY_SERVER with the name of your Usenet server.
Please post the results here.

[Olivier-fr]

Hi,

I have the same issue. Ubuntu 11.10 + SabNZBd 0.7.0Beta3. Works great with previous version.

Here my log :

Code: Select all

2012-05-04 03:00:01,667::INFO::[_cplogging:55] [04/May/2012:03:00:01] ENGINE Re-spawning /usr/bin/sabnzbdplus --daemon
2012-05-04 03:00:06,126::INFO::[_cplogging:55] [04/May/2012:03:00:06] ENGINE Bus STARTING
2012-05-04 03:00:06,166::INFO::[_cplogging:55] [04/May/2012:03:00:06] ENGINE Started monitor thread '_TimeoutMonitor'.
2012-05-04 03:00:06,384::INFO::[_cplogging:55] [04/May/2012:03:00:06] ENGINE Serving on 0.0.0.0:8080
2012-05-04 03:00:06,588::INFO::[_cplogging:55] [04/May/2012:03:00:06] ENGINE Serving on 0.0.0.0:9090
2012-05-04 03:00:06,589::INFO::[_cplogging:55] [04/May/2012:03:00:06] ENGINE Bus STARTED
2012-05-04 13:25:06,790::INFO::[downloader:588] Thread 2@news.supernews.com:443: Article 999999999999@JBinUp.local missing (error=430)
2012-05-04 13:25:06,806::INFO::[decoder:194] <Article: article=999999999999@JBinUp.local, bytes=398507, partnum=111, art_id=None> => absents de tous les serveurs, rejeté
2012-05-04 13:25:06,882::INFO::[downloader:588] Thread 1@news.supernews.com:443: Article 999999999999@JBinUp.local missing (error=430)
2012-05-04 13:25:06,883::INFO::[decoder:194] <Article: article=999999999999@JBinUp.local, bytes=398557, partnum=112, art_id=None> => absents de tous les serveurs, rejeté
2012-05-04 13:25:07,518::INFO::[downloader:588] Thread 1@news.supernews.com:443: Article 999999999999@JBinUp.local missing (error=430)
2012-05-04 13:25:07,519::INFO::[decoder:194] <Article: article=999999999999@JBinUp.local, bytes=398442, partnum=114, art_id=None> => absents de tous les serveurs, rejeté
2012-05-04 13:25:07,607::INFO::[downloader:588] Thread 2@news.supernews.com:443: Article 999999999999@JBinUp.local missing (error=430)
2012-05-04 13:25:07,608::INFO::[decoder:194] <Article: article=999999999999@JBinUp.local, bytes=398358, partnum=113, art_id=None> => absents de tous les serveurs, rejeté
2012-05-04 13:25:08,148::INFO::[downloader:588] Thread 1@news.supernews.com:443: Article 999999999999@JBinUp.local missing (error=430)
2012-05-04 13:25:08,177::INFO::[decoder:194] <Article: article=999999999999@JBinUp.local, bytes=398559, partnum=115, art_id=None> => absents de tous les serveurs, rejeté
2012-05-04 13:25:08,324::INFO::[downloader:588] Thread 2@news.supernews.com:443: Article 999999999999@JBinUp.local missing (error=430)
2012-05-04 13:25:08,325::INFO::[decoder:194] <Article: article=999999999999@JBinUp.local, bytes=398419, partnum=116, art_id=None> => absents de tous les serveurs, rejeté
2012-05-04 13:25:08,828::INFO::[downloader:588] Thread 1@news.supernews.com:443: Article 999999999999@JBinUp.local missing (error=430)
2012-05-04 13:25:08,829::INFO::[decoder:194] <Article: article=999999999999@JBinUp.local, bytes=398207, partnum=117, art_id=None> => absents de tous les serveurs, rejeté
2012-05-04 13:25:08,962::INFO::[downloader:588] Thread 2@news.supernews.com:443: Article 999999999999@JBinUp.local missing (error=430)
2012-05-04 13:25:08,963::INFO::[decoder:194] <Article: article=999999999999@JBinUp.local, bytes=398390, partnum=118, art_id=None> => absents de tous les serveurs, rejeté
2012-05-04 13:25:09,445::INFO::[downloader:588] Thread 1@news.supernews.com:443: Article 999999999999@JBinUp.local missing (error=430)
2012-05-04 13:25:09,446::INFO::[decoder:194] <Article: article=999999999999@JBinUp.local, bytes=398652, partnum=119, art_id=None> => absents de tous les serveurs, rejeté
2012-05-04 13:25:09,578::INFO::[downloader:588] Thread 2@news.supernews.com:443: Article 999999999999@JBinUp.local missing (error=430)
2012-05-04 13:25:09,579::INFO::[decoder:194] <Article: article=999999999999@JBinUp.local, bytes=398665, partnum=120, art_id=None> => absents de tous les serveurs, rejeté
2012-05-04 13:25:10,076::INFO::[downloader:588] Thread 1@news.supernews.com:443: Article 999999999999@JBinUp.local missing (error=430)
2012-05-04 13:25:10,076::INFO::[decoder:194] <Article: article=999999999999@JBinUp.local, bytes=398390, partnum=121, art_id=None> => absents de tous les serveurs, rejeté
2012-05-04 13:25:10,209::INFO::[downloader:588] Thread 2@news.supernews.com:443: Article 999999999999@JBinUp.local missing (error=430)
2012-05-04 13:25:10,209::INFO::[decoder:194] <Article: article=999999999999@JBinUp.local, bytes=398532, partnum=122, art_id=None> => absents de tous les serveurs, rejeté
2012-05-04 13:25:10,701::INFO::[downloader:588] Thread 1@news.supernews.com:443: Article 999999999999@JBinUp.local missing (error=430)
2012-05-04 13:25:10,702::INFO::[decoder:194] <Article: article=999999999999@JBinUp.local, bytes=398551, partnum=123, art_id=None> => absents de tous les serveurs, rejeté
2012-05-04 13:25:10,825::INFO::[downloader:588] Thread 2@news.supernews.com:443: Article 999999999999@JBinUp.local missing (error=430)
2012-05-04 13:25:10,826::INFO::[decoder:194] <Article: article=999999999999@JBinUp.local, bytes=398586, partnum=124, art_id=None> => absents de tous les serveurs, rejeté
2012-05-04 13:25:11,357::INFO::[downloader:588] Thread 1@news.supernews.com:443: Article 999999999999@JBinUp.local missing (error=430)
2012-05-04 13:25:11,358::INFO::[decoder:194] <Article: article=999999999999@JBinUp.local, bytes=398462, partnum=125, art_id=None> => absents de tous les serveurs, rejeté
2012-05-04 13:25:11,454::INFO::[downloader:588] Thread 2@news.supernews.com:443: Article 999999999999@JBinUp.local missing (error=430)
2012-05-04 13:25:11,455::INFO::[decoder:194] <Article: article=999999999999@JBinUp.local, bytes=398418, partnum=126, art_id=None> => absents de tous les serveurs, rejeté
2012-05-04 13:25:12,070::INFO::[downloader:588] Thread 2@news.supernews.com:443: Article 999999999999@JBinUp.local missing (error=430)
2012-05-04 13:25:12,071::INFO::[decoder:194] <Article: article=999999999999@JBinUp.local, bytes=398470, partnum=128, art_id=None> => absents de tous les serveurs, rejeté
2012-05-04 13:25:12,133::INFO::[downloader:588] Thread 1@news.supernews.com:443: Article 999999999999@JBinUp.local missing (error=430)
2012-05-04 13:25:12,134::INFO::[decoder:194] <Article: article=999999999999@JBinUp.local, bytes=398389, partnum=127, art_id=None> => absents de tous les serveurs, rejeté
2012-05-04 13:25:12,686::INFO::[downloader:588] Thread 2@news.supernews.com:443: Article 999999999999@JBinUp.local missing (error=430)
2012-05-04 13:25:12,687::INFO::[decoder:194] <Article: article=999999999999@JBinUp.local, bytes=398551, partnum=129, art_id=None> => absents de tous les serveurs, rejeté
2012-05-04 13:25:12,758::INFO::[downloader:588] Thread 1@news.supernews.com:443: Article 999999999999@JBinUp.local missing (error=430)
2012-05-04 13:25:12,759::INFO::[decoder:194] <Article: article=999999999999@JBinUp.local, bytes=398469, partnum=130, art_id=None> => absents de tous les serveurs, rejeté
2012-05-04 13:25:13,333::INFO::[downloader:588] Thread 2@news.supernews.com:443: Article 999999999999@JBinUp.local missing (error=430)
2012-05-04 13:25:13,335::INFO::[decoder:194] <Article: article=999999999999@JBinUp.local, bytes=398444, partnum=131, art_id=None> => absents de tous les serveurs, rejeté
2012-05-04 13:25:13,375::INFO::[downloader:588] Thread 1@news.supernews.com:443: Article 999999999999@JBinUp.local missing (error=430)
2012-05-04 13:25:13,376::INFO::[decoder:194] <Article: article=999999999999@JBinUp.local, bytes=398392, partnum=132, art_id=None> => absents de tous les serveurs, rejeté
2012-05-04 13:25:14,036::INFO::[downloader:588] Thread 1@news.supernews.com:443: Article 999999999999@JBinUp.local missing (error=430)
2012-05-04 13:25:14,037::INFO::[decoder:194] <Article: article=999999999999@JBinUp.local, bytes=398484, partnum=134, art_id=None> => absents de tous les serveurs, rejeté


I can't check multiple IP adresses now but I will in few days. By the way, Sabnzbd correctly switch to my backup server.


Thanks,
Olivier

[sander]

Olivier, you use news.supernews.com, which only has got one ip address.

Sander

[shypike]

Also, just the fact that an article is missing doesn't mean that SABnzbd fails,
the server is likely not to have it.
Silverlock also has very frequent time-outs, which is not the same as only having a missing article.

[jcfp]

Olivier-fr's log shows sab receiving an explicit response from the server saying the article isn't available (note the 430 error code). That's everything working as it should, except the end user not being happy with the resulting failed jobs. His log is snipped a bit too much, but I bet the download threads only needed connecting once and after that things would have just worked if all parts had been available on the server.

This is not the case for silverlock, where the log shows a rapid succession of threads repeatedly connecting and disconnecting (for no apparent reason), followed by sab giving up. There's no evidence the article was actually ever requested or the server responding to such a request if it was made.

[Silverlock]

That leaves #4.
Can you check whether your Usenet server has multiple IP addresses.

It definitely does have multiple addresses. The resolution looks something like this:

Code: Select all

Server:         127.0.0.1
Address:        127.0.0.1#53

Non-authoritative answer:
news.city.provider.net       canonical name = news.provider.net.
news.provider.net      canonical name = newsfarm.xyz.highwinds-media.com.
Name:   newsfarm.xyz.highwinds-media.com
Address: 99.66.888.250
Name:   newsfarm.xyz.highwinds-media.com
Address: 99.66.888.247


EDIT: I tried editing the hostip function downloader.py to always return a single IP and compiled it; it didn't seem to make a difference which one I used. I even had it return the original fqdn as it would in the case of a single IP; same result. I verified that it was in fact using a single IP by turning on the +info logging. Darn; I really thought that might be it.

[shypike]

Darn; I really thought that might be it.

That's exactly what I thought.
BTW: you need to return just the self.host value.

Back to the drawing board for new suggestions.
I hope you have the patience to hang on.
It's very valuable for me to deal with a knowlegable user, so
this issue can be cracked.

[Silverlock]

I've no problem hanging on to see if we can resolve this. I have 0.6.15 working where I need it to be and I have an 0.7 installation on another box that I can tinker with as required. Python isn't my strong suit (so many languages, so little time!), but I'm comfortable reading it and making small changes to existing code to try things.

[shypike]

Sent you an email with a patched file.

[Silverlock]

I've got bad news and good news.

The bad news is that the patched download.py didn't make any difference.

The good news is that I found the code that appears to be causing the problem.

After the patched download.py didn't make any difference I decided to start with a 0.6.15 download.py and make the minimal changes to it to get it work with 0.7. I did, and the problems continued.

Figuring that newswrapper.py was also intimately involved in the downloading, I went after it next. The code changes there were truly minimal (only 4 sections of code). I decided to hack it back to 0.6.15 status (which involved changing the call to body(), removing the if's for precheck and oddball and taking out the incorrect newline-only check). And it worked. No dropped connections, no erroneously flagged missing articles, no problems.

I started again with the 0.7 code and changed one section of code at a time. In the end, this bit was the offender:

Code: Select all

         # See if incorrect newline-only was used
         # Do this as a special case to prevent using extra memory
         # for normal articles
         if len(new_lines) == 1 and '\r' not in data:
             new_lines = self.data.split('\n')

To double check, I removed and reinstalled sabnzbd so that I knew I had a clean copy of 0.7. I then removed the one block of code from newswrapper.py, compiled it and started sabnzbd up. I fed it an nzb and it worked.

I see what the block of code is trying to do; it's breaking the data up into lines regardless of whether the line terminator was a crlf pair or lf alone. Why it would cause the issues I'm seeing... I have no idea.