Downloader keeps crashing

[rickatnight11]

My Ubuntu 12.04 server has been downloading steadily today, when all of a sudden I noticed my download speed at 0 KB/s. I checked the logs and found that the downloader keeps crashing, causing sabnzbd to reload:

Code: Select all

2012-07-16 17:48:06,460::INFO::[downloader:375] [email protected]:563: Initiating connection
2012-07-16 17:48:06,461::INFO::[downloader:375] [email protected]:563: Initiating connection
2012-07-16 17:48:06,462::INFO::[downloader:375] [email protected]:563: Initiating connection
2012-07-16 17:48:06,463::INFO::[downloader:375] [email protected]:563: Initiating connection
2012-07-16 17:48:06,464::INFO::[downloader:375] [email protected]:563: Initiating connection
2012-07-16 17:48:06,464::INFO::[downloader:375] [email protected]:563: Initiating connection
2012-07-16 17:48:06,465::INFO::[downloader:375] [email protected]:563: Initiating connection
2012-07-16 17:48:06,466::INFO::[downloader:375] [email protected]:563: Initiating connection
2012-07-16 17:48:06,467::INFO::[downloader:375] [email protected]:563: Initiating connection
2012-07-16 17:48:06,468::INFO::[downloader:375] [email protected]:563: Initiating connection
2012-07-16 17:48:38,486::INFO::[__init__:994] Restarting because of crashed downloader
2012-07-16 17:48:40,310::INFO::[__init__:350] SABnzbd shutting down...
----yadda yadda------
2012-07-16 17:48:42,459::INFO::[sabnzbdplus:1529] Starting sabnzbdplus-0.7.1
2012-07-16 17:48:42,462::INFO::[dirscanner:265] Dirscanner starting up
2012-07-16 17:48:42,463::INFO::[urlgrabber:78] URLGrabber starting up
2012-07-16 17:48:43,463::INFO::[downloader:375] [email protected]:563: Initiating connection
2012-07-16 17:48:43,464::INFO::[downloader:375] [email protected]:563: Initiating connection
2012-07-16 17:48:43,465::INFO::[downloader:375] [email protected]:563: Initiating connection
2012-07-16 17:48:43,466::INFO::[downloader:375] [email protected]:563: Initiating connection
----wash, rinse, repeat------

The rest of the app is responsive, as I'm able to remove and readd those downloads, but as soon as it starts to "dial out" to my usenet provider, the same issue occurs. One thing I've noticed, which may or may not be responsible, is the following error whenever I try an access the Servers section on the Config page:

Code: Select all

2012-07-16 17:54:17,857::INFO::[_cplogging:55] [16/Jul/2012:17:54:17] HTTP 
Request Headers:
  AUTHORIZATION: Basic -----
  X-FORWARDED-SERVER: -----
  REFERER: -----
  X-FORWARDED-HOST:-----
  ORIGIN: -----
  Content-Length: 30
  ACCEPT-CHARSET: ISO-8859-1,utf-8;q=0.7,*;q=0.3
  CONNECTION: Keep-Alive
  COOKIE: jqCookieJar_tablesorter=-----; plushQueuePerPage=20; plushHistPerPage=20; advanced_toggle_checked=1; plushMultiOps=0; plushContainerWidth=100%25; plushNoTopMenu=0
  Remote-Addr: 127.0.0.1
  X-REQUESTED-WITH: XMLHttpRequest
  USER-AGENT: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_6_8) AppleWebKit/537.1 (KHTML, like Gecko) Chrome/21.0.1180.41 Safari/537.1
  HOST: xxxxx
  ACCEPT: */*
  ACCEPT-LANGUAGE: en-US,en;q=0.8
  X-FORWARDED-FOR: 204.14.236.210
  Content-Type: application/x-www-form-urlencoded
  ACCEPT-ENCODING: gzip,deflate,sdch
2012-07-16 17:54:17,858::DEBUG::[_cplogging:55] [16/Jul/2012:17:54:17] HTTP Traceback (most recent call last):
  File "/usr/share/sabnzbdplus/cherrypy/_cprequest.py", line 618, in respond
    cherrypy.response.body = self.handler()
  File "/usr/share/sabnzbdplus/cherrypy/_cpdispatch.py", line 25, in __call__
    return self.callable(*self.args, **self.kwargs)
  File "/usr/share/sabnzbdplus/sabnzbd/interface.py", line 866, in index
    grand, month, week, day = BPSMeter.do.get_sums()
  File "/usr/share/sabnzbdplus/sabnzbd/bpsmeter.py", line 248, in get_sums
    return (sum([v for v in self.grand_total.values()]),
TypeError: unsupported operand type(s) for +: 'int' and 'str'

2012-07-16 17:54:21,388::INFO::[_cplogging:55] [16/Jul/2012:17:54:21] HTTP 
Request Headers:
  AUTHORIZATION: Basic [auth removed/jcfp]
  X-FORWARDED-SERVER: ----
  REFERER:----
  X-FORWARDED-HOST: -----
  ACCEPT-CHARSET: ISO-8859-1,utf-8;q=0.7,*;q=0.3
  CONNECTION: Keep-Alive
  COOKIE: jqCookieJar_tablesorter=------; plushQueuePerPage=20; plushHistPerPage=20; advanced_toggle_checked=1; plushMultiOps=0; plushContainerWidth=100%25; plushNoTopMenu=0
  Remote-Addr: 127.0.0.1
  USER-AGENT: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_6_8) AppleWebKit/537.1 (KHTML, like Gecko) Chrome/21.0.1180.41 Safari/537.1
  HOST: -----
  ACCEPT: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
  ACCEPT-LANGUAGE: en-US,en;q=0.8
  X-FORWARDED-FOR: [ip removed/jcfp]
  ACCEPT-ENCODING: gzip,deflate,sdch
2012-07-16 17:54:21,389::DEBUG::[_cplogging:55] [16/Jul/2012:17:54:21] HTTP Traceback (most recent call last):
  File "/usr/share/sabnzbdplus/cherrypy/_cprequest.py", line 618, in respond
    cherrypy.response.body = self.handler()
  File "/usr/share/sabnzbdplus/cherrypy/_cpdispatch.py", line 25, in __call__
    return self.callable(*self.args, **self.kwargs)
  File "/usr/share/sabnzbdplus/sabnzbd/interface.py", line 1464, in index
    new[svr]['amounts'] = to_units(t), to_units(m), to_units(w), to_units(d)
  File "/usr/share/sabnzbdplus/sabnzbd/misc.py", line 639, in to_units
    val = str(abs(val)).strip()
TypeError: bad operand type for abs(): 'str'

That page throws a "500 Internal Server Error".

[shypike]

Hmm, a case of having too little paranoia in coding.
I'll see whether I can fix this on the basis of this info.

Could you dig a little further into the logging?
The crashes you show are in the UI, not in the downloader.
UI crashes are not fatal for actual downloading.

[rickatnight11]

Gotcha. The code sample at the top was from the regular log, so I'll see what the error log says.

[rickatnight11]

My error log is flooded with these:

Code: Select all

** (sabnzbdplus:7205): WARNING **: Error spawning command line `dbus-launch --autolaunch=764a3e7b825671619376c58c00000192 --binary-syntax --close-stderr': Failed to create pipe for communicating with child process (Too many open files)
Exception in thread Thread-3:
Traceback (most recent call last):
  File "/usr/lib/python2.7/threading.py", line 551, in __bootstrap_inner
    self.run()
  File "/usr/share/sabnzbdplus/sabnzbd/downloader.py", line 479, in run
    BPSMeter.do.update(server.id, bytes)
  File "/usr/share/sabnzbdplus/sabnzbd/bpsmeter.py", line 206, in update
    self.grand_total[server] += amount
TypeError: cannot concatenate 'str' and 'int' objects

If I'm reading this right, it looks like my total download stats have hit a certain number that the code's not prepared to handle....or there's just a datatype handling bug in the code. I prefer to think I downloaded so much I broke sab.

[shypike]

Do the "WARNING" message and the downloader crash message always go together?
The warning does not look like anything coming from SABnzbd itself, but from the Python runtimes.
Are you using an Debian/Ubuntu package?
(sabnzbdplus:7205) could be coming from the launch script of a package.
Which SABnzbd version is this?

As for the downloader crash, it's a case of trying to add a number to a (numerical) string.
Python is a bit tricky in that it's always a surprise when duck-typing will be used and when not...
But it's a clear error in the code.
The tricky question to be answered is: why has "self.grand_total[server]" become a string instead of an integer?

Can you make the following little patch in the bpsmeter.py file?
Replace line 206 with these:

Code: Select all

    try:
        self.grand_total[server] += amount
    except TypeError:
        logging.debug('GRAND_TOTAL[%s] is now "%s" of type %s', server, self.grand_total[server], type(self.grand_total[server]))
        raise TypeError

Can you tell anything about the circumstances when it happens?

[rickatnight11]

The WARNING error only happens when sab starts up....I think that's unrelated. That's just erroring that it can't initialize X11, which makes sense, since I'm starting this from an SSH session as a daemon. (Not sure why it's actually trying to initialize X11. Maybe I have that set in my config somewhere.)

The TypeError does correlate with the crash. It fires every time the usenet connections initiate.

The new code is raising the TypeError, as expected:

Code: Select all

Exception in thread Thread-3:
Traceback (most recent call last):
  File "/usr/lib/python2.7/threading.py", line 551, in __bootstrap_inner
    self.run()
  File "/usr/share/sabnzbdplus/sabnzbd/downloader.py", line 479, in run
    BPSMeter.do.update(server.id, bytes)
  File "/usr/share/sabnzbdplus/sabnzbd/bpsmeter.py", line 210, in update
    raise TypeError
TypeError

...and after I changed the logging level to include DEBUG, it's logging:

Code: Select all

2012-07-17 13:09:11,150::DEBUG::[bpsmeter:209] GRAND_TOTAL[news.giganews.com] is now "
" of type <type 'str'>

Are you using the wrong variable or passing the wrong value into that variable?

[exussum]

are you running this from a VPS ? if so is it super cheap ?

" (Too many open files)"

What is the result of cat /proc/user_beancounters as i assume your running under open vz

The x11 is likely pointed towards localhost:0 but your not running anything to show it. You should be able to disable it pretty easy

[shypike]

If I'm reading this right, it looks like my total download stats have hit a certain number that the code's not prepared to handle....or there's just a
datatype handling bug in the code. I prefer to think I downloaded so much I broke sab.

Unlikely, in Python short int are smoothly converted into long int when needed, good luck overflowing that.
When the crash occurs again, can you make a copy of the file totals9.sab in the "admin" folder
and email it to [email protected] ?

[rickatnight11]

are you running this from a VPS ? if so is it super cheap ?

" (Too many open files)"

No, I'm running my own physical server (PowerEdge 1850.) I found that odd, too, considering my ulimit is unlimited.

[exussum]

What else is running ? Have you tried lowering the connection count to maybe 2 ? and increasing until there is a problem ?
Heres output from a bnc server i run

# ulimit
unlimited
# ulimit -n
1024


So Although it says unlimited - it really means 1024

[rickatnight11]

What else is running ? Have you tried lowering the connection count to maybe 2 ? and increasing until there is a problem ?
Heres output from a bnc server i run

# ulimit
unlimited
# ulimit -n
1024


So Although it says unlimited - it really means 1024

Huh, interesting. Good to know. The only thing I can think of that'd exhaust that number would be rtorrent. I'll stop a few other things to see if that helps, but the logs still seem to indicate a bug, so I don't want to do too much until we've exhausted that option.

[exussum]

What else is running ? Have you tried lowering the connection count to maybe 2 ? and increasing until there is a problem ?
Heres output from a bnc server i run

# ulimit
unlimited
# ulimit -n
1024


So Although it says unlimited - it really means 1024

Huh, interesting. Good to know. The only thing I can think of that'd exhaust that number would be rtorrent. I'll stop a few other things to see if that helps, but the logs still seem to indicate a bug, so I don't want to do too much until we've exhausted that option.

rtorrent is killer for open files stop rtorrent, Try sab again if it works look at either raising the limit or limiting rtorrent or see how many its using

lsof | grep 1234 | wc -l

where 1234 is the pid of rtorrent

[rickatnight11]

When the crash occurs again, can you make a copy of the file totals9.sab in the "admin" folder
and email it to [email protected] ?

It happens constantly, and thus none of my downloads work at the moment. I've just emailed the file.

[shypike]

The content is bizarre and so far I have no explanation.
The counter for the giganews server is "\r\n" instead of a number.
This is what makes the code crash.
I have just added parameter validation to the code that reads totals9.sab from disk.
That solves the crash but will not solve the root cause.

For you the work-around is to stop SABnzbd, remove the totals9.sab file and start again.
This will destroy your byte counters though.

I'm completely puzzled about what the cause is, but I'll try to find it.

[rickatnight11]

rtorrent is killer for open files stop rtorrent, Try sab again if it works look at either raising the limit or limiting rtorrent or see how many its using

lsof | grep 1234 | wc -l

where 1234 is the pid of rtorrent

Total open file count was at 5,000, and after I stopped rtorrent, jdownloader, and killed an NX session I had running, that dropped to 500. Unfortunately sab is exhibiting the same issue. I think the file limit is another unrelated alert.