Learning to Troubleshoot sabnzbd

[petro]

As a newbie, I'm trying to learn how to troubleshoot why sabnzbd isn't downloading items in my queue. Here's some information on my current state and log files. I've searched through the docs and forums and wiki and can't quite find out how to see what sabnzbd is or isn't doing...

Yesterday I manually uploaded an NZB file and sabnzbd successfully downloaded the files. So in principle the connection to my news provider via ssl is all working fine. It also says so when I test the connection.

I have 15 items in my queue currently. The queue does not appear to be paused, however nothing is downloading, and if I tcpdump packets on the server filtering for any traffic to my news server, there's nothing being send/received. If I click the "test" button to my news server, I do see packets sent.

I've stopped and started the process, to no avail. Below is the latest log entries, including when I restarted the process. Note that I've snipped out the log entries for most of the filenames in the queue, leaving one for example.

I've re-ordered entries in my queue, and verified the files do exist on the news server. No luck.

I've tried turning on a more detailed logging level to no avail. How can I figure out why sabnzbd is not trying to initiate a download of any files in my queue? Is there some more obvious form of logging or debugging I'm missing, or a way to make sure I've not set some random option that's causing sabnzbd to not even try??

Thanks,
-petro



2012-04-12 12:13:36,856::INFO::[__init__:846] Saving data for queue9.sab in /home/atv/.sabnzbd/admin/queue9.sab
2012-04-12 12:13:36,857::INFO::[__init__:846] Saving data for totals9.sab in /home/atv/.sabnzbd/admin/totals9.sab
2012-04-12 12:13:36,857::INFO::[__init__:846] Saving data for rss_data.sab in /home/atv/.sabnzbd/admin/rss_data.sab
2012-04-12 12:13:36,858::INFO::[__init__:846] Saving data for bookmarks.sab in /home/atv/.sabnzbd/admin/bookmarks.sab
2012-04-12 12:13:36,858::INFO::[__init__:846] Saving data for watched_data.sab in /home/atv/.sabnzbd/admin/watched_data.sab
2012-04-12 12:13:36,859::INFO::[postproc:83] Saving postproc queue
2012-04-12 12:13:36,863::INFO::[__init__:846] Saving data for postproc1.sab in /home/atv/.sabnzbd/admin/postproc1.sab
2012-04-12 12:13:43,057::INFO::[sabnzbdplus:1195] --------------------------------
2012-04-12 12:13:43,058::INFO::[sabnzbdplus:1196] sabnzbdplus-0.6.15 (rev=d06f957a0f05a8766822acaa6de1f6d1e9f279e0)
2012-04-12 12:13:43,058::INFO::[sabnzbdplus:1208] Platform = posix
2012-04-12 12:13:43,058::INFO::[sabnzbdplus:1209] Python-version = 2.5.2 (r252:60911, Jan 20 2010, 21:48:48)
[GCC 4.2.4 (Ubuntu 4.2.4-1ubuntu3)]
2012-04-12 12:13:43,059::INFO::[sabnzbdplus:1210] Arguments = "/usr/bin/sabnzbdplus", "--daemon", "--config-file", "/home/atv/.sabnzbd/sabnzbd.ini", "--server", "0.0.0.0:8001", "--logging=2"
2012-04-12 12:13:43,059::INFO::[sabnzbdplus:1223] Read INI file /home/atv/.sabnzbd/sabnzbd.ini
2012-04-12 12:13:43,073::INFO::[__init__:870] Loading data for bookmarks.sab from /home/atv/.sabnzbd/admin/bookmarks.sab
2012-04-12 12:13:43,073::INFO::[__init__:870] Loading data for rss_data.sab from /home/atv/.sabnzbd/admin/rss_data.sab
2012-04-12 12:13:43,074::INFO::[__init__:870] Loading data for totals9.sab from /home/atv/.sabnzbd/admin/totals9.sab
2012-04-12 12:13:43,074::INFO::[postproc:89] Loading postproc queue
2012-04-12 12:13:43,075::INFO::[__init__:870] Loading data for postproc1.sab from /home/atv/.sabnzbd/admin/postproc1.sab
2012-04-12 12:13:43,075::INFO::[__init__:870] Loading data for queue9.sab from /home/atv/.sabnzbd/admin/queue9.sab
2012-04-12 12:13:43,076::DEBUG::[__init__:805] Loading data for SABnzbd_nzo_hQVIvo from /home/atv/xbmclibrary/incomplete/SomeShow.720p.HDTV.x264-2HD/__ADMIN__/SABnzbd_nzo_hQVIvo

<********SNIP********>

2012-04-12 12:13:43,253::DEBUG::[downloader:110] Initializing downloader/decoder
2012-04-12 12:13:43,254::INFO::[__init__:870] Loading data for watched_data.sab from /home/atv/.sabnzbd/admin/watched_data.sab
2012-04-12 12:13:43,255::DEBUG::[scheduler:136] Scheduling RSS interval task every 60 min (delay=27)
2012-04-12 12:13:43,256::DEBUG::[scheduler:147] Scheduling VersionCheck on day 1 at 8:28
2012-04-12 12:13:43,256::INFO::[downloader:194] Resuming
2012-04-12 12:13:43,256::DEBUG::[__init__:479] PAUSED_ALL inactive
2012-04-12 12:13:43,257::INFO::[__init__:289] All processes started
2012-04-12 12:13:43,257::INFO::[sabnzbdplus:332] Web dir is /usr/share/sabnzbdplus/interfaces/Plush
2012-04-12 12:13:43,291::INFO::[sabnzbdplus:442] _yenc module... found!
2012-04-12 12:13:43,304::INFO::[sabnzbdplus:450] par2 binary... found (/usr/bin/par2)
2012-04-12 12:13:43,304::INFO::[sabnzbdplus:458] unrar binary... found (/usr/bin/unrar)
2012-04-12 12:13:43,305::INFO::[sabnzbdplus:463] unzip binary... found (/usr/bin/unzip)
2012-04-12 12:13:43,305::INFO::[sabnzbdplus:469] nice binary... found (/usr/bin/nice)
2012-04-12 12:13:43,305::INFO::[sabnzbdplus:473] ionice binary... found (/usr/bin/ionice)
2012-04-12 12:13:43,305::INFO::[sabnzbdplus:478] pyOpenSSL... found (True)
2012-04-12 12:13:43,328::INFO::[sabnzbdplus:1390] Starting web-interface on 0.0.0.0:8001
2012-04-12 12:13:43,330::INFO::[_cplogging:55] [12/Apr/2012:12:13:43] ENGINE Bus STARTING
2012-04-12 12:13:43,391::INFO::[_cplogging:55] [12/Apr/2012:12:13:43] ENGINE Started monitor thread '_TimeoutMonitor'.
2012-04-12 12:13:43,608::INFO::[_cplogging:55] [12/Apr/2012:12:13:43] ENGINE Serving on 0.0.0.0:8001
2012-04-12 12:13:43,609::INFO::[_cplogging:55] [12/Apr/2012:12:13:43] ENGINE Bus STARTED
2012-04-12 12:13:43,609::DEBUG::[misc:522] Version check disabled by Ubuntu/Debian packaging
2012-04-12 12:13:43,610::INFO::[sabnzbdplus:1459] Starting sabnzbdplus-0.6.15
2012-04-12 12:13:43,610::DEBUG::[__init__:300] Starting postprocessor
2012-04-12 12:13:43,639::DEBUG::[__init__:303] Starting assembler
2012-04-12 12:13:43,644::DEBUG::[__init__:306] Starting downloader
2012-04-12 12:13:43,652::DEBUG::[scheduler:172] Starting scheduler
2012-04-12 12:13:43,652::DEBUG::[__init__:311] Starting dirscanner
2012-04-12 12:13:43,653::INFO::[dirscanner:263] Dirscanner starting up
2012-04-12 12:13:43,653::DEBUG::[__init__:316] Starting urlgrabber
2012-04-12 12:13:43,654::INFO::[urlgrabber:75] URLGrabber starting up

[sander]

Is SABnzbd globally paused by pressing on the button in the upper right corner?
What is the number of connections you have specified for your newsserver?
Is your harddisk full?

What happens when you stop SABnzbd as a service/daemon, and just type "sabnzbdplus" from the command line?

[petro]

Thanks sander. No, I've clicked and clicked on the global pause button to make sure, and you can see the results in the logs above when I do.

Connections to the news server is set to 8, though I'm not even seeing one tried.

Stopping the daemon and running from the command line output below, though it seems from tcpdumping there's no communication going on to the news server. How else can I see activity of what the process is meant to be doing?

Thanks!




root@atv:~# /usr/bin/sabnzbdplus -f ~atv/.sabnzbd/sabnzbd.ini
2012-04-12 18:46:51,946::INFO::[sabnzbdplus:1195] --------------------------------
2012-04-12 18:46:51,947::INFO::[sabnzbdplus:1196] sabnzbdplus-0.6.15 (rev=d06f957a0f05a8766822acaa6de1f6d1e9f279e0)
2012-04-12 18:46:51,947::INFO::[sabnzbdplus:1208] Platform = posix
2012-04-12 18:46:51,948::INFO::[sabnzbdplus:1209] Python-version = 2.5.2 (r252:60911, Jan 20 2010, 21:48:48)
[GCC 4.2.4 (Ubuntu 4.2.4-1ubuntu3)]
2012-04-12 18:46:51,948::INFO::[sabnzbdplus:1210] Arguments = "/usr/bin/sabnzbdplus", "-f", "/home/atv/.sabnzbd/sabnzbd.ini"
2012-04-12 18:46:51,949::INFO::[sabnzbdplus:1223] Read INI file /home/atv/.sabnzbd/sabnzbd.ini
2012-04-12 18:46:51,954::INFO::[__init__:870] Loading data for bookmarks.sab from /home/atv/.sabnzbd/admin/bookmarks.sab
2012-04-12 18:46:51,955::INFO::[__init__:870] Loading data for rss_data.sab from /home/atv/.sabnzbd/admin/rss_data.sab
2012-04-12 18:46:51,956::INFO::[__init__:870] Loading data for totals9.sab from /home/atv/.sabnzbd/admin/totals9.sab
2012-04-12 18:46:51,957::INFO::[postproc:89] Loading postproc queue
2012-04-12 18:46:51,957::INFO::[__init__:870] Loading data for postproc1.sab from /home/atv/.sabnzbd/admin/postproc1.sab
2012-04-12 18:46:51,958::INFO::[__init__:870] Loading data for queue9.sab from /home/atv/.sabnzbd/admin/queue9.sab
2012-04-12 18:46:51,963::DEBUG::[__init__:805] Loading data for SABnzbd_nzo_hQVIvo from /home/atv/xbmclibrary/incomplete/Top.Chef.S09E18.Reunion.720p.HDTV.x264-2HD/__ADMIN__/SABnzbd_nzo_hQVIvo

<SNIP>

2012-04-12 18:46:52,389::DEBUG::[downloader:110] Initializing downloader/decoder
2012-04-12 18:46:52,390::INFO::[__init__:870] Loading data for watched_data.sab from /home/atv/.sabnzbd/admin/watched_data.sab
2012-04-12 18:46:52,391::DEBUG::[scheduler:136] Scheduling RSS interval task every 60 min (delay=31)
2012-04-12 18:46:52,396::DEBUG::[scheduler:147] Scheduling VersionCheck on day 2 at 1:50
2012-04-12 18:46:52,397::INFO::[downloader:194] Resuming
2012-04-12 18:46:52,397::DEBUG::[__init__:479] PAUSED_ALL inactive
2012-04-12 18:46:52,398::INFO::[__init__:289] All processes started
2012-04-12 18:46:52,398::INFO::[sabnzbdplus:332] Web dir is /usr/share/sabnzbdplus/interfaces/Plush
2012-04-12 18:46:52,414::INFO::[sabnzbdplus:442] _yenc module... found!
2012-04-12 18:46:52,414::INFO::[sabnzbdplus:450] par2 binary... found (/usr/bin/par2)
2012-04-12 18:46:52,415::INFO::[sabnzbdplus:458] unrar binary... found (/usr/bin/unrar)
2012-04-12 18:46:52,415::INFO::[sabnzbdplus:463] unzip binary... found (/usr/bin/unzip)
2012-04-12 18:46:52,416::INFO::[sabnzbdplus:469] nice binary... found (/usr/bin/nice)
2012-04-12 18:46:52,416::INFO::[sabnzbdplus:473] ionice binary... found (/usr/bin/ionice)
2012-04-12 18:46:52,417::INFO::[sabnzbdplus:478] pyOpenSSL... found (True)
2012-04-12 18:46:52,419::INFO::[sabnzbdplus:1390] Starting web-interface on 0.0.0.0:8001
2012-04-12 18:46:52,420::INFO::[_cplogging:55] [12/Apr/2012:18:46:52] ENGINE Bus STARTING
2012-04-12 18:46:52,425::INFO::[_cplogging:55] [12/Apr/2012:18:46:52] ENGINE Started monitor thread '_TimeoutMonitor'.
2012-04-12 18:46:52,527::INFO::[_cplogging:55] [12/Apr/2012:18:46:52] ENGINE Serving on 0.0.0.0:8001
2012-04-12 18:46:52,528::INFO::[_cplogging:55] [12/Apr/2012:18:46:52] ENGINE Bus STARTED
2012-04-12 18:46:52,529::DEBUG::[misc:522] Version check disabled by Ubuntu/Debian packaging
2012-04-12 18:46:52,529::INFO::[sabnzbdplus:1459] Starting sabnzbdplus-0.6.15
2012-04-12 18:46:52,529::DEBUG::[__init__:300] Starting postprocessor
2012-04-12 18:46:52,532::DEBUG::[__init__:303] Starting assembler
2012-04-12 18:46:52,532::DEBUG::[__init__:306] Starting downloader
2012-04-12 18:46:52,533::DEBUG::[scheduler:172] Starting scheduler
2012-04-12 18:46:52,534::DEBUG::[__init__:311] Starting dirscanner
2012-04-12 18:46:52,534::INFO::[dirscanner:263] Dirscanner starting up
2012-04-12 18:46:52,535::DEBUG::[__init__:316] Starting urlgrabber
2012-04-12 18:46:52,535::INFO::[urlgrabber:75] URLGrabber starting up

[sander]

Well, hard to say what's going on.

Two things I can think of:
- add a random newsserver (for example: news.kpn.nl, 3 connections), and see if that is contacted. (If so, SAB will say it needs a account/password).
- last resort: stop sabnzbd, mv /home/atv/.sabnzbd/ to something else, start sabnzbdplus: it should start the wizard. Fill it out, and see if SAB works afterwards.

[petro]

Thanks Sander, good advice, thankfully I didn't have to go that far... I noticed the problem while randomly looking at one of the config files. The news server was disabled, thus no contact. I never noticed the "Enable" checkbox on the webui before. Grrrr, stupid problem. I knew it was going to be... Thanks for the help.

[sander]

Thanks Sander, good advice, thankfully I didn't have to go that far... I noticed the problem while randomly looking at one of the config files. The news server was disabled, thus no contact. I never noticed the "Enable" checkbox on the webui before. Grrrr, stupid problem. I knew it was going to be... Thanks for the help.

Ouc! So I must expand my check list from

Is SABnzbd globally paused by pressing on the button in the upper right corner?
What is the number of connections you have specified for your newsserver?
Is your harddisk full?

to

Is SABnzbd globally paused by pressing on the button in the upper right corner?
What is the number of connections you have specified for your newsserver?
Is your newsserver enabled?
Is your harddisk full?

Thanks!

[petro]

Sounds like you may have to! Thanks again for the fast replies.