SABnzb using 100% CPU time and new downloads appearing as orphaned jobs

[ErikBrown]

Version: 6.2 final but it also happened with 6.1 and I think also with 6.0
OS: Windows XP SP3
Install-type: Windows Installer
Skin (if applicable): Smpl
Firewall Software: None
Are you using IPV6? no
Is the issue reproducible? No, it happens only every now and then
PC: Pentium 3, 1 GHz with 512 MB memory

Sometimes SABnzbd starts taking up continuously 100% CPU time. This is shown in Windows taskmanager. When I do not notice this and put some NZB files in the Watched folder (while SABnzbd uses up 100% of the CPU time), then these files will not be added to the download queue but show up on the Warnings page as orphaned jobs. When this happens, I notice that it takes a long time (a minute or two while I have configured to check every 15 seconds for new NZB files in the Watched folder) before the NZBs are removed from the Watched folder. So maybe this is caused by a timeout? Note that my PC is always very slow and this is even much worse when SABnzbd goes into such a tight loop.

If I then shut down SABnzbd (using the normal shutdown link) then it takes about 35 minutes before I see in the browser that it has been shut down. But according to taskmanager the SABnzbd process stays running at 100%.

To recover, I tell Windows to shutdown and then I see in taskmanager after a few seconds that SABnzbd stops running and then Windows shuts down. When the PC is rebooted and SABnzbd has started again, then I add the files again in the Warnings page by clicking on the Add buttons. Taskmanager shows then that SABnzbd takes as normal about 35% CPU time during downloading (at 8Mb/s).

The log shows that SABnzbd restarts very frequently. Here is a smal section of the log. I have replaced the download file path with X'es but the path length is still about the same, it is 263 characters. Is maybe the path too long and does the frequent restarts cause sometimes the tight loop? Not all files with too long path cause SABnzbd to consume 100% CPU time. Note that the download files with the long pathnames are put in the queue by a RSS feed.

The following is part of the log:

2011-05-25 16:45:40,135::ERROR::[assembler:92] Disk error on creating file C:\SABnzbd\incomplete\xxxxxxxxxxxxxxxxxxxx xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx\xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx.part46.rar

2011-05-25 16:48:31,913::INFO::[_cplogging:55] [25/May/2011:16:48:31] ENGINE Bus STOPPING

2011-05-25 16:48:32,023::INFO::[_cplogging:55] [25/May/2011:16:48:32] ENGINE HTTP Server cherrypy._cpwsgi_server.CPWSGIServer(('192.168.1.5', 8090)) shut down

2011-05-25 16:48:32,033::INFO::[_cplogging:55] [25/May/2011:16:48:32] ENGINE Stopped thread '_TimeoutMonitor'.

2011-05-25 16:48:32,033::INFO::[_cplogging:55] [25/May/2011:16:48:32] ENGINE Bus STOPPED

2011-05-25 16:48:32,033::INFO::[_cplogging:55] [25/May/2011:16:48:32] ENGINE Bus EXITING

2011-05-25 16:48:32,033::INFO::[_cplogging:55] [25/May/2011:16:48:32] ENGINE Bus EXITED

2011-05-25 16:48:32,033::INFO::[_cplogging:55] [25/May/2011:16:48:32] ENGINE Re-spawning C:\Program Files\SABnzbd\SABnzbd.exe --autorestarted

2011-05-25 16:48:39,434::INFO::[_cplogging:55] [25/May/2011:16:48:39] ENGINE Bus STARTING

2011-05-25 16:48:39,453::INFO::[_cplogging:55] [25/May/2011:16:48:39] ENGINE Started monitor thread '_TimeoutMonitor'.

2011-05-25 16:48:39,654::INFO::[_cplogging:55] [25/May/2011:16:48:39] ENGINE Serving on 192.168.1.5:8090

2011-05-25 16:48:39,654::INFO::[_cplogging:55] [25/May/2011:16:48:39] ENGINE Bus STARTED

2011-05-25 16:49:36,266::ERROR::[assembler:92] Disk error on creating file C:\SABnzbd\incomplete\xxxxxxxxxxxxxxxxxxxx xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx\xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx.part48.rar

2011-05-25 16:52:09,826::INFO::[_cplogging:55] [25/May/2011:16:52:09] ENGINE Bus STOPPING

2011-05-25 16:52:09,937::INFO::[_cplogging:55] [25/May/2011:16:52:09] ENGINE HTTP Server cherrypy._cpwsgi_server.CPWSGIServer(('192.168.1.5', 8090)) shut down

2011-05-25 16:52:09,967::INFO::[_cplogging:55] [25/May/2011:16:52:09] ENGINE Stopped thread '_TimeoutMonitor'.

2011-05-25 16:52:09,967::INFO::[_cplogging:55] [25/May/2011:16:52:09] ENGINE Bus STOPPED

2011-05-25 16:52:09,967::INFO::[_cplogging:55] [25/May/2011:16:52:09] ENGINE Bus EXITING

2011-05-25 16:52:09,967::INFO::[_cplogging:55] [25/May/2011:16:52:09] ENGINE Bus EXITED

2011-05-25 16:52:09,967::INFO::[_cplogging:55] [25/May/2011:16:52:09] ENGINE Re-spawning C:\Program Files\SABnzbd\SABnzbd.exe --autorestarted

2011-05-25 16:52:17,388::INFO::[_cplogging:55] [25/May/2011:16:52:17] ENGINE Bus STARTING

2011-05-25 16:52:17,398::INFO::[_cplogging:55] [25/May/2011:16:52:17] ENGINE Started monitor thread '_TimeoutMonitor'.

2011-05-25 16:52:17,598::INFO::[_cplogging:55] [25/May/2011:16:52:17] ENGINE Serving on 192.168.1.5:8090

2011-05-25 16:52:17,598::INFO::[_cplogging:55] [25/May/2011:16:52:17] ENGINE Bus STARTED

2011-05-25 16:53:33,836::ERROR::[assembler:92] Disk error on creating file C:\SABnzbd\incomplete\xxxxxxxxxxxxxxxxxxxx xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx\xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx.part50.rar


2011-05-25 20:04:44,450::INFO::[_cplogging:55] [25/May/2011:20:04:44] HTTP
Request Headers:
  REFERER: http://192.168.1.5:8090/sabnzbd/
  HOST: 192.168.1.5:8090
  X-REQUESTED-WITH: XMLHttpRequest
  ACCEPT: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
  ACCEPT-CHARSET: ISO-8859-1,utf-8;q=0.7,*;q=0.7
  USER-AGENT: Mozilla/5.0 (Windows NT 6.1; WOW64; rv:2.0.1) Gecko/20100101 Firefox/4.0.1
  CONNECTION: keep-alive
  COOKIE: smplrefresh=300; queue_details=1; speedlog2=326,784,784,0,761,748,945,946,929,151,177,906,912,773,428,747,745,756,273,228; smplrefresh=300; plushContainerWidth=100%25; plushNoTopMenu=0; plushFailedOnly=0; queue_details=1; speedlog2=0,0,0,948,945,944,945,947,945,947,940,940,943,947,88,944,943,947,939,932; session_id=ebc1cb99f1f77819d452a3ba69b5bd637f7df603
  Remote-Addr: 192.168.1.3
  ACCEPT-LANGUAGE: en-us,en;q=0.5
  ACCEPT-ENCODING: gzip, deflate
  KEEP-ALIVE: 115

2011-05-25 20:04:44,460::DEBUG::[_cplogging:55] [25/May/2011:20:04:44] HTTP Traceback (most recent call last):
  File "cherrypy\_cprequest.pyo", line 618, in respond
  File "cherrypy\_cpdispatch.pyo", line 25, in __call__
  File "sabnzbd\interface.pyo", line 491, in default
  File "cheetah__Program_Files_SABnzbd_interfaces_smpl_templates_nzo_tmpl_1306339484_42_78854.py", line 99, in respond
NotFound: cannot find 'filename' while searching for 'slot.filename'


2011-05-25 20:08:35,973::ERROR::[downloader:658] Suspect error in downloader

2011-05-25 21:31:01,595::ERROR::[_cplogging:55] [25/May/2011:21:31:01]  Traceback (most recent call last):
  File "cherrypy\_cpwsgi.pyo", line 79, in setapp
  File "cherrypy\_cpwsgi.pyo", line 219, in get_response
  File "cherrypy\_cprequest.pyo", line 579, in run
TimeoutError


Regards,
Erik

[shypike]

Hard to tell.
There are lots of suspect messages in the log, but it could all be fall-out of something else.
I'd normally say: check your disk and permissions when I see "Disk error on creating file C:\SABnzbd\incomplete\..."
The restarts are likely caused by the internal watchdog that monitors the various threads.
When one stops (because of a hangup or crash), it restarts SABnzbd.
Unfortunately I do not see any message about which thread it is.

I'm not trying to pass on the blame, but it is rather old hardware
In short: I don't see enough info in the log to say anything useful about causes.