Api call for history is crashing sabnzbd

[cltdba]

I came across this issue after upgraded CouchPotatoServer to v2. It checks the queue and download history to check download status of movies it has sent to sabnzbd.

I am running SABnzbd v0.7.3 on OS X 10.7.5.

SABnzbd is hitting 100% cpu usage and then crashes with a segmentation fault when an api call is made with mode=history. (See test urls below.) This is directly related to the amount of download history. I have (had) a significant amount of history. If I had to guess, I'd say well over 500 downloads between failed and completed. If limits are placed on the api call then it returns successfully up to "some sweet number". I tried with limits of 2, 10, 15, 20, 50 and 200. 0-50 worked fine, but 200 crashed. I did not try anything in between those limits. Once I purged my completed download history, I no longer faced the crashing problem regardless of limiting the resultset. This also means I cannot recreate the problem again. (Without restoring from backup...)

I tested with both output=json and output=xml. XML output spiked the CPU and caused SABnzbd to hang, but did not end in a segmentation fault. I had to kill the process.

Test URLs:

Code: Select all

http://localhost:8080/api?output=json&apikey=MyApiKey&mode=queue
http://localhost:8080/api?output=json&apikey=MyApiKey&mode=history
http://localhost:8080/api?output=json&apikey=MyApiKey&mode=history&start=0&limit=2

http://localhost:8080/api?output=xml&apikey=MyApiKey&mode=queue
http://localhost:8080/api?output=xml&apikey=MyApiKey&mode=history
http://localhost:8080/api?output=xml&apikey=MyApiKey&mode=history&start=0&limit=2

Sample SABnzbd Console :

Code: Select all

DEBUG:root:API-call from ::1 {'output': 'json', 'apikey': '&myapikey', 'mode': 'queue'}
INFO:cherrypy.access.4479998864:::1 - - [21/Sep/2012:00:36:14] "GET /api?output=json&apikey=&myapikey&mode=queue HTTP/1.1" 200 1219 "localhost" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10.7; rv:10.0.2) Gecko/20100101 Firefox/10.0.2"
DEBUG:root:API-call from ::1 {'output': 'json', 'apikey': '&myapikey', 'mode': 'history'}
Segmentation fault: 11

Sample SABnzbd debug log : (I've removed my apikey.)

Code: Select all

2012-09-21 00:36:14,759::DEBUG::[interface:400] API-call from ::1 {'output': 'json', 'apikey': '&myapikey', 'mode': 'queue'}
2012-09-21 00:36:14,769::DEBUG::[interface:400] API-call from ::1 {'output': 'json', 'apikey': '&myapikey', 'mode': 'history'}
 

CouchPotatoServer Log:

Code: Select all

09-21 00:36:14 INFO [0m[.core.downloaders.sabnzbd] Checking download status of "Foobar 1" at SABnzbd.[0m
09-21 00:36:14 INFO [0m[hpotato.core.plugins.base] Opening url: http://localhost:8080/api?output=json&apikey=xxx&mode=queue, params: [][0m
09-21 00:36:14 INFO [0m[hpotato.core.plugins.base] Opening url: http://localhost:8080/api?output=json&apikey=xxx&mode=history, params: [][0m
09-21 00:36:41 ERROR [31m[.core.downloaders.sabnzbd] Failed getting history: Traceback (most recent call last):
  File "/Applications/CouchPotatoServer/couchpotato/core/downloaders/sabnzbd/main.py", line 108, in getDownloadStatus
    sab = self.urlopen(url, timeout = 60, show_error = False)
  File "/Applications/CouchPotatoServer/couchpotato/core/plugins/base.py", line 141, in urlopen
    response = urllib2.urlopen(request, timeout = timeout)
  File "/System/Library/Frameworks/Python.framework/Versions/2.7/lib/python2.7/urllib2.py", line 126, in urlopen
    return _opener.open(url, data, timeout)
  File "/System/Library/Frameworks/Python.framework/Versions/2.7/lib/python2.7/urllib2.py", line 394, in open
    response = self._open(req, data)
  File "/System/Library/Frameworks/Python.framework/Versions/2.7/lib/python2.7/urllib2.py", line 412, in _open
    '_open', req)
  File "/System/Library/Frameworks/Python.framework/Versions/2.7/lib/python2.7/urllib2.py", line 372, in _call_chain
    result = func(*args)
  File "/System/Library/Frameworks/Python.framework/Versions/2.7/lib/python2.7/urllib2.py", line 1199, in http_open
    return self.do_open(httplib.HTTPConnection, req)
  File "/System/Library/Frameworks/Python.framework/Versions/2.7/lib/python2.7/urllib2.py", line 1170, in do_open
    r = h.getresponse(buffering=True)
  File "/System/Library/Frameworks/Python.framework/Versions/2.7/lib/python2.7/httplib.py", line 1013, in getresponse
    response.begin()
  File "/System/Library/Frameworks/Python.framework/Versions/2.7/lib/python2.7/httplib.py", line 402, in begin
    version, status, reason = self._read_status()
  File "/System/Library/Frameworks/Python.framework/Versions/2.7/lib/python2.7/httplib.py", line 366, in _read_status
    raise BadStatusLine(line)
BadStatusLine: ''
[0m
09-21 00:36:41 INFO [0m[.core.downloaders.sabnzbd] Checking download status of "Foobar 2" at SABnzbd.[0m
09-21 00:36:41 INFO [0m[hpotato.core.plugins.base] Opening url: http://localhost:8080/api?output=json&apikey=xxx&mode=queue, params: [][0m
09-21 00:36:41 ERROR [31m[.core.downloaders.sabnzbd] Failed checking status: Traceback (most recent call last):
  File "/Applications/CouchPotatoServer/couchpotato/core/downloaders/sabnzbd/main.py", line 82, in getDownloadStatus
    sab = self.urlopen(url, timeout = 60, show_error = False)
  File "/Applications/CouchPotatoServer/couchpotato/core/plugins/base.py", line 141, in urlopen
    response = urllib2.urlopen(request, timeout = timeout)
  File "/System/Library/Frameworks/Python.framework/Versions/2.7/lib/python2.7/urllib2.py", line 126, in urlopen
    return _opener.open(url, data, timeout)
  File "/System/Library/Frameworks/Python.framework/Versions/2.7/lib/python2.7/urllib2.py", line 394, in open
    response = self._open(req, data)
  File "/System/Library/Frameworks/Python.framework/Versions/2.7/lib/python2.7/urllib2.py", line 412, in _open
    '_open', req)
  File "/System/Library/Frameworks/Python.framework/Versions/2.7/lib/python2.7/urllib2.py", line 372, in _call_chain
    result = func(*args)
  File "/System/Library/Frameworks/Python.framework/Versions/2.7/lib/python2.7/urllib2.py", line 1199, in http_open
    return self.do_open(httplib.HTTPConnection, req)
  File "/System/Library/Frameworks/Python.framework/Versions/2.7/lib/python2.7/urllib2.py", line 1174, in do_open
    raise URLError(err)
URLError: <urlopen error [Errno 61] Connection refused>
[0m

[shypike]

Do you have a very large History?

[cltdba]

Yep, sure "did". I have already fixed the crashing issue by purging the history. Like I said above, if I had to guess I would say I had over 500 downloads in the history. Before this issue popped up, I never purged.

[shypike]

I think CounchPotato makes error by asking for a full history content every few seconds.
What does it need that for?
May I suggest that you file a complaint with CP too?

[cltdba]

Yep, I've already raised the issue with CPS. I'm not sure of their plans, but will ask if they would consider a revision. I believe the purpose of this is to avoid duplicate downloads. For example, perhaps I manually added an nzb to sabnzb and then also had CPS search for the same thing in order to find higher quality versions. CPS appears to use sab download history as a repository or point of reference so it does not duplicate. I will try to determine if that is they intention behind the full history scan.


I read a thread here that version 0.8.0 may include the ability to specify a download ID or range of IDs; start/end. I think this would help third party developer to avoid pulling the full history.

[shypike]

Noting wrong with a full history scan, but not every few seconds...

[cltdba]

In looking at the CPS logs, it appears it does a history scan once a minute while there are items it expects sabnzbd to be downloading.

By the way, you do you realize that I was able to produce the behavior via my browser right? CPS was shut down. I restarted sabnzbd, gave it about 5 minutes "initialize" and then made a full history scan using the url above. The sabnzbd process hit 100% CPU and then died with sig11/segmentation fault.

[shypike]

I don't think we ever tested it with such a large history
and unlimited display.
DOS attacks are easy

[cltdba]

Perhaps you could add a config item to limit full history scan requests to whatever number is configured? Maybe 50-75 by default? Maybe even as little as 20? I know I don't snatch 50 at a time, others may? Perhaps it would be an advanced option?

I got to thinking further about what you said about CPS requesting the history ever couple of seconds and I figured out why it seems that way. CPS seems to submit 1 queue and 1 full history scan for each snatched movie at the top of every minute. So, if you have 2 snatched movies, you would get two separate history requests each minute. So it's actually submitting multiple requests per sub-second!

I also posted this finding on the CPS forum for the CPS team to ponder it for a bit.

sabnzbd log:

Code: Select all

2012-09-21 18:08:50,820::DEBUG::[interface:400] API-call from ::1 {'output': 'json', 'apikey': 'MyApiKey', 'mode': 'queue'}
2012-09-21 18:08:50,825::DEBUG::[interface:400] API-call from ::1 {'output': 'json', 'apikey': 'MyApiKey', 'mode': 'history'}
2012-09-21 18:08:50,872::DEBUG::[interface:400] API-call from ::1 {'output': 'json', 'apikey': 'MyApiKey', 'mode': 'queue'}
2012-09-21 18:08:50,877::DEBUG::[interface:400] API-call from ::1 {'output': 'json', 'apikey': 'MyApiKey', 'mode': 'history'}
2012-09-21 18:09:50,819::DEBUG::[interface:400] API-call from ::1 {'output': 'json', 'apikey': 'MyApiKey', 'mode': 'queue'}
2012-09-21 18:09:50,824::DEBUG::[interface:400] API-call from ::1 {'output': 'json', 'apikey': 'MyApiKey', 'mode': 'history'}
2012-09-21 18:09:50,874::DEBUG::[interface:400] API-call from ::1 {'output': 'json', 'apikey': 'MyApiKey', 'mode': 'queue'}
2012-09-21 18:09:50,879::DEBUG::[interface:400] API-call from ::1 {'output': 'json', 'apikey': 'MyApiKey', 'mode': 'history'}
2012-09-21 18:10:50,827::DEBUG::[interface:400] API-call from ::1 {'output': 'json', 'apikey': 'MyApiKey', 'mode': 'queue'}
2012-09-21 18:10:50,832::DEBUG::[interface:400] API-call from ::1 {'output': 'json', 'apikey': 'MyApiKey', 'mode': 'history'}
2012-09-21 18:10:50,878::DEBUG::[interface:400] API-call from ::1 {'output': 'json', 'apikey': 'MyApiKey', 'mode': 'queue'}
2012-09-21 18:10:50,884::DEBUG::[interface:400] API-call from ::1 {'output': 'json', 'apikey': 'MyApiKey', 'mode': 'history'}

CPS Log:

Code: Select all

09-21 18:08:50 INFO [0m[.core.downloaders.sabnzbd] Checking download status of "Magic.Mike.2012.XviD-CM8 magic.mike.2012.dvdrip.xvid.ac3-5.1.hq.hive-cm8 .cp(tt1915581)" at SABnzbd.[0m
09-21 18:08:50 INFO [0m[hpotato.core.plugins.base] Opening url: http://localhost:8080/api?output=json&apikey=xxx&mode=queue, params: [][0m
09-21 18:08:50 INFO [0m[hpotato.core.plugins.base] Opening url: http://localhost:8080/api?output=json&apikey=xxx&mode=history, params: [][0m
09-21 18:08:50 ERROR [31m[.core.downloaders.sabnzbd] Failed parsing history json: Traceback (most recent call last):
  File "/Applications/CouchPotatoServer/couchpotato/core/downloaders/sabnzbd/main.py", line 114, in getDownloadStatus
    history = json.loads(sab)
  File "/System/Library/Frameworks/Python.framework/Versions/2.7/lib/python2.7/json/__init__.py", line 326, in loads
    return _default_decoder.decode(s)
  File "/System/Library/Frameworks/Python.framework/Versions/2.7/lib/python2.7/json/decoder.py", line 360, in decode
    obj, end = self.raw_decode(s, idx=_w(s, 0).end())
  File "/System/Library/Frameworks/Python.framework/Versions/2.7/lib/python2.7/json/decoder.py", line 376, in raw_decode
    obj, end = self.scan_once(s, idx)
ValueError: Invalid control character at: line 1 column 150778 (char 150778)
[0m
09-21 18:08:50 INFO [0m[.core.downloaders.sabnzbd] Checking download status of "(Ted.2012.DVDRip.XviD-AsA)  - Ted.2012.DVDRip.XviD-AsA .cp(tt1637725)" at SABnzbd.[0m
09-21 18:08:50 INFO [0m[hpotato.core.plugins.base] Opening url: http://localhost:8080/api?output=json&apikey=xxx&mode=queue, params: [][0m
09-21 18:08:50 INFO [0m[hpotato.core.plugins.base] Opening url: http://localhost:8080/api?output=json&apikey=xxx&mode=history, params: [][0m
09-21 18:08:50 ERROR [31m[.core.downloaders.sabnzbd] Failed parsing history json: Traceback (most recent call last):
  File "/Applications/CouchPotatoServer/couchpotato/core/downloaders/sabnzbd/main.py", line 114, in getDownloadStatus
    history = json.loads(sab)
  File "/System/Library/Frameworks/Python.framework/Versions/2.7/lib/python2.7/json/__init__.py", line 326, in loads
    return _default_decoder.decode(s)
  File "/System/Library/Frameworks/Python.framework/Versions/2.7/lib/python2.7/json/decoder.py", line 360, in decode
    obj, end = self.raw_decode(s, idx=_w(s, 0).end())
  File "/System/Library/Frameworks/Python.framework/Versions/2.7/lib/python2.7/json/decoder.py", line 376, in raw_decode
    obj, end = self.scan_once(s, idx)
ValueError: Invalid control character at: line 1 column 150778 (char 150778)
[0m
09-21 18:09:50 INFO [0m[.core.downloaders.sabnzbd] Checking download status of "Magic.Mike.2012.XviD-CM8 magic.mike.2012.dvdrip.xvid.ac3-5.1.hq.hive-cm8 .cp(tt1915581)" at SABnzbd.[0m
09-21 18:09:50 INFO [0m[hpotato.core.plugins.base] Opening url: http://localhost:8080/api?output=json&apikey=xxx&mode=queue, params: [][0m
09-21 18:09:50 INFO [0m[hpotato.core.plugins.base] Opening url: http://localhost:8080/api?output=json&apikey=xxx&mode=history, params: [][0m
09-21 18:09:50 ERROR [31m[.core.downloaders.sabnzbd] Failed parsing history json: Traceback (most recent call last):
  File "/Applications/CouchPotatoServer/couchpotato/core/downloaders/sabnzbd/main.py", line 114, in getDownloadStatus
    history = json.loads(sab)
  File "/System/Library/Frameworks/Python.framework/Versions/2.7/lib/python2.7/json/__init__.py", line 326, in loads
    return _default_decoder.decode(s)
  File "/System/Library/Frameworks/Python.framework/Versions/2.7/lib/python2.7/json/decoder.py", line 360, in decode
    obj, end = self.raw_decode(s, idx=_w(s, 0).end())
  File "/System/Library/Frameworks/Python.framework/Versions/2.7/lib/python2.7/json/decoder.py", line 376, in raw_decode
    obj, end = self.scan_once(s, idx)
ValueError: Invalid control character at: line 1 column 150778 (char 150778)
[0m
09-21 18:09:50 INFO [0m[.core.downloaders.sabnzbd] Checking download status of "(Ted.2012.DVDRip.XviD-AsA)  - Ted.2012.DVDRip.XviD-AsA .cp(tt1637725)" at SABnzbd.[0m
09-21 18:09:50 INFO [0m[hpotato.core.plugins.base] Opening url: http://localhost:8080/api?output=json&apikey=xxx&mode=queue, params: [][0m
09-21 18:09:50 INFO [0m[hpotato.core.plugins.base] Opening url: http://localhost:8080/api?output=json&apikey=xxx&mode=history, params: [][0m
09-21 18:09:50 ERROR [31m[.core.downloaders.sabnzbd] Failed parsing history json: Traceback (most recent call last):
  File "/Applications/CouchPotatoServer/couchpotato/core/downloaders/sabnzbd/main.py", line 114, in getDownloadStatus
    history = json.loads(sab)
  File "/System/Library/Frameworks/Python.framework/Versions/2.7/lib/python2.7/json/__init__.py", line 326, in loads
    return _default_decoder.decode(s)
  File "/System/Library/Frameworks/Python.framework/Versions/2.7/lib/python2.7/json/decoder.py", line 360, in decode
    obj, end = self.raw_decode(s, idx=_w(s, 0).end())
  File "/System/Library/Frameworks/Python.framework/Versions/2.7/lib/python2.7/json/decoder.py", line 376, in raw_decode
    obj, end = self.scan_once(s, idx)
ValueError: Invalid control character at: line 1 column 150778 (char 150778)
[0m
09-21 18:10:50 INFO [0m[.core.downloaders.sabnzbd] Checking download status of "Magic.Mike.2012.XviD-CM8 magic.mike.2012.dvdrip.xvid.ac3-5.1.hq.hive-cm8 .cp(tt1915581)" at SABnzbd.[0m
09-21 18:10:50 INFO [0m[hpotato.core.plugins.base] Opening url: http://localhost:8080/api?output=json&apikey=xxx&mode=queue, params: [][0m
09-21 18:10:50 INFO [0m[hpotato.core.plugins.base] Opening url: http://localhost:8080/api?output=json&apikey=xxx&mode=history, params: [][0m
09-21 18:10:50 ERROR [31m[.core.downloaders.sabnzbd] Failed parsing history json: Traceback (most recent call last):
  File "/Applications/CouchPotatoServer/couchpotato/core/downloaders/sabnzbd/main.py", line 114, in getDownloadStatus
    history = json.loads(sab)
  File "/System/Library/Frameworks/Python.framework/Versions/2.7/lib/python2.7/json/__init__.py", line 326, in loads
    return _default_decoder.decode(s)
  File "/System/Library/Frameworks/Python.framework/Versions/2.7/lib/python2.7/json/decoder.py", line 360, in decode
    obj, end = self.raw_decode(s, idx=_w(s, 0).end())
  File "/System/Library/Frameworks/Python.framework/Versions/2.7/lib/python2.7/json/decoder.py", line 376, in raw_decode
    obj, end = self.scan_once(s, idx)
ValueError: Invalid control character at: line 1 column 150778 (char 150778)
[0m
09-21 18:10:50 INFO [0m[.core.downloaders.sabnzbd] Checking download status of "(Ted.2012.DVDRip.XviD-AsA)  - Ted.2012.DVDRip.XviD-AsA .cp(tt1637725)" at SABnzbd.[0m
09-21 18:10:50 INFO [0m[hpotato.core.plugins.base] Opening url: http://localhost:8080/api?output=json&apikey=xxx&mode=queue, params: [][0m
09-21 18:10:50 INFO [0m[hpotato.core.plugins.base] Opening url: http://localhost:8080/api?output=json&apikey=xxx&mode=history, params: [][0m
09-21 18:10:50 ERROR [31m[.core.downloaders.sabnzbd] Failed parsing history json: Traceback (most recent call last):
  File "/Applications/CouchPotatoServer/couchpotato/core/downloaders/sabnzbd/main.py", line 114, in getDownloadStatus
    history = json.loads(sab)
  File "/System/Library/Frameworks/Python.framework/Versions/2.7/lib/python2.7/json/__init__.py", line 326, in loads
    return _default_decoder.decode(s)
  File "/System/Library/Frameworks/Python.framework/Versions/2.7/lib/python2.7/json/decoder.py", line 360, in decode
    obj, end = self.raw_decode(s, idx=_w(s, 0).end())
  File "/System/Library/Frameworks/Python.framework/Versions/2.7/lib/python2.7/json/decoder.py", line 376, in raw_decode
    obj, end = self.scan_once(s, idx)
ValueError: Invalid control character at: line 1 column 150778 (char 150778)
[0m

[shypike]

Yeah, that's probably a safe solution.
Although the problem should really be tackled by CouchPotato.

[clinton hall]

Ruud has implemented a limit of 15. This is in the develop branch and should go to master at he next merge.

Also, in CPS settings, renamer, set Run Every (advanced option) to a greater time. This will reduce the frequency of calls.

[shypike]

Good, I added the safety measure all the same.

[cltdba]

Ruud has implemented a limit of 15. This is in the develop branch and should go to master at he next merge.

Also, in CPS settings, renamer, set Run Every (advanced option) to a greater time. This will reduce the frequency of calls.

Cool, set it to 10 minutes.

[Ommi]

For what it is worth (and I'm not sure if this will help, hinder, or is just random irrelevant noise), but my history is up to ~5200 items (7MB or so) and it returns without a hitch. Perhaps not quickly, but always makes it home.

This is, of course, an aside to the question of "is it really necessary to request a full history every minute", but I'm not sure a large history in itself is sufficient to cause the freeze.

And now, back to lurking!

[shypike]

That may be so, but if multiple overlapping queries are made, chances are that will lead to problems.
It also depends on how much memory your system has.
Anyway, there's a fix in 0.7.4RC1.