sabnzbd keeps crashing [debian]

[milomak]

I am running it on debian stable. the below is what the log shows between just before it crashed and when i restarted it

Code: Select all

2014-01-15 22:08:53,958::INFO::[_cplogging:55] [15/Jan/2014:22:08:53] HTTP 
Request Headers:
  AUTHORIZATION: Basic REMOVED
  REFERER: http://192.168.1.102:8080/
  Content-Length: 35
  USER-AGENT: Mozilla/5.0 (X11; Linux x86_64; rv:26.0) Gecko/20100101 Firefox/26.0
  CONNECTION: keep-alive
  COOKIE: plushContainerWidth=100%25; plushNoTopMenu=0; plushHistPerPage=9999999; advanced_toggle_checked=1; plushMultiOps=0; plushBlockRefresh=0; plushQueuePerPage=9999999; wanted_view2=details; snatched_view2=list; soon_view2=thumbs; late_view2=list; manage_view2=details
  Remote-Addr: 192.168.1.100
  PRAGMA: no-cache
  X-REQUESTED-WITH: XMLHttpRequest
  DNT: 1
  HOST: 192.168.1.102:8080
  CACHE-CONTROL: no-cache
  ACCEPT: */*
  ACCEPT-LANGUAGE: en-gb,en;q=0.5
  Content-Type: application/x-www-form-urlencoded; charset=UTF-8
  ACCEPT-ENCODING: gzip, deflate
2014-01-15 22:08:54,128::DEBUG::[_cplogging:55] [15/Jan/2014:22:08:54] 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 880, in index
    return template.respond()
  File "_usr_share_sabnzbdplus_interfaces_Plush_templates_history_tmpl.py", line 286, in respond
NotFound: cannot find 'actions' while searching for 'stage.actions'

2014-01-15 22:32:07,717::INFO::[_cplogging:55] [15/Jan/2014:22:32:07] ENGINE Bus STARTING

mod edit: care with those http headers, "AUTHORIZATION: Basic [...]" contains your (base64-encoded) credentials. Removed now.

[shypike]

Remove the history1.db file.
You'll loose your download history though.

[milomak]

that's a small price to pay. thanks.

[shypike]

I'll see if I can make SABnzbd handle this more elegantly.

[milomak]

it continued to crash so i enabled debugging. here is a bit more extensive log

Code: Select all

$ cat /mnt/mythtv/sabnzb/logs/sabnzbd.log | grep -b10 -a10 ERROR
2544827-2014-01-20 19:45:12,508::INFO::[sabnzbdplus:442] _yenc module... found!
2544899-2014-01-20 19:45:12,509::INFO::[sabnzbdplus:450] par2 binary... found (/usr/bin/par2)
2544985-2014-01-20 19:45:12,509::INFO::[sabnzbdplus:458] unrar binary... found (/usr/bin/unrar)
2545073-2014-01-20 19:45:12,509::INFO::[sabnzbdplus:463] unzip binary... found (/usr/bin/unzip)
2545161-2014-01-20 19:45:12,509::INFO::[sabnzbdplus:469] nice binary... found (/usr/bin/nice)
2545247-2014-01-20 19:45:12,510::INFO::[sabnzbdplus:473] ionice binary... found (/usr/bin/ionice)
2545337-2014-01-20 19:45:12,510::INFO::[sabnzbdplus:478] pyOpenSSL... found (True)
2545412-2014-01-20 19:45:12,513::INFO::[sabnzbdplus:1390] Starting web-interface on 192.168.1.102:8080
2545507-2014-01-20 19:45:12,515::INFO::[_cplogging:55] [20/Jan/2014:19:45:12] ENGINE Bus STARTING
2545597-2014-01-20 19:45:12,691::INFO::[_cplogging:55] [20/Jan/2014:19:45:12] ENGINE Started monitor thread '_TimeoutMonitor'.
2545716:2014-01-20 19:45:12,694::ERROR::[_cplogging:55] [20/Jan/2014:19:45:12] ENGINE Error in HTTP server: shutting down
2545830-Traceback (most recent call last):
2545865-  File "/usr/share/sabnzbdplus/cherrypy/process/servers.py", line 75, in _start_http_thread
2545957-    self.httpserver.start()
2545985-  File "/usr/share/sabnzbdplus/cherrypy/wsgiserver/__init__.py", line 1644, in start
2546070-    raise socket.error, msg
2546098-error: [Errno 99] Cannot assign requested address
2546148-
2546149-2014-01-20 19:45:12,694::INFO::[_cplogging:55] [20/Jan/2014:19:45:12] ENGINE Bus STOPPING
2546239-2014-01-20 19:45:12,695::INFO::[_cplogging:55] [20/Jan/2014:19:45:12] ENGINE HTTP Server cherrypy._cpwsgi_server.CPWSGIServer(('192.168.1.102', 8080)) already shut down
2546408-2014-01-20 19:45:12,698::INFO::[_cplogging:55] [20/Jan/2014:19:45:12] ENGINE Stopped thread '_TimeoutMonitor'.
2546519-2014-01-20 19:45:12,698::INFO::[_cplogging:55] [20/Jan/2014:19:45:12] ENGINE Bus STOPPED
2546608-2014-01-20 19:45:12,698::INFO::[_cplogging:55] [20/Jan/2014:19:45:12] ENGINE Bus EXITING
2546697-2014-01-20 19:45:12,699::INFO::[_cplogging:55] [20/Jan/2014:19:45:12] ENGINE Bus EXITED
2546785:2014-01-20 19:45:12,793::ERROR::[_cplogging:55] [20/Jan/2014:19:45:12] ENGINE Error in 'start' listener <bound method Server.start of <cherrypy._cpserver.Server object at 0x292bfd0>>
2546968-Traceback (most recent call last):
2547003-  File "/usr/share/sabnzbdplus/cherrypy/process/wspbus.py", line 147, in publish
2547084-    output.append(listener(*args, **kwargs))
2547129-  File "/usr/share/sabnzbdplus/cherrypy/_cpserver.py", line 90, in start
2547202-    ServerAdapter.start(self)
2547232-  File "/usr/share/sabnzbdplus/cherrypy/process/servers.py", line 62, in start
2547311-    self.wait()
2547327-  File "/usr/share/sabnzbdplus/cherrypy/process/servers.py", line 97, in wait
2547405-    raise self.interrupt
2547430-error: [Errno 99] Cannot assign requested address
2547480-
2547481:2014-01-20 19:45:12,794::ERROR::[_cplogging:55] [20/Jan/2014:19:45:12] ENGINE Shutting down due to error in start listener:
2547605-Traceback (most recent call last):
2547640-  File "/usr/share/sabnzbdplus/cherrypy/process/wspbus.py", line 184, in start
2547719-    self.publish('start')
2547745-  File "/usr/share/sabnzbdplus/cherrypy/process/wspbus.py", line 147, in publish
2547826-    output.append(listener(*args, **kwargs))
2547871-  File "/usr/share/sabnzbdplus/cherrypy/_cpserver.py", line 90, in start
2547944-    ServerAdapter.start(self)
2547974-  File "/usr/share/sabnzbdplus/cherrypy/process/servers.py", line 62, in start
2548053-    self.wait()
2548069-  File "/usr/share/sabnzbdplus/cherrypy/process/servers.py", line 97, in wait
2548147-    raise self.interrupt
2548172-error: [Errno 99] Cannot assign requested address
2548222-
2548223-2014-01-20 19:45:12,794::INFO::[_cplogging:55] [20/Jan/2014:19:45:12] ENGINE Bus STOPPING
2548313-2014-01-20 19:45:12,794::INFO::[_cplogging:55] [20/Jan/2014:19:45:12] ENGINE HTTP Server cherrypy._cpwsgi_server.CPWSGIServer(('192.168.1.102', 8080)) already shut down
2548482-2014-01-20 19:45:12,794::INFO::[_cplogging:55] [20/Jan/2014:19:45:12] ENGINE No thread running for _TimeoutMonitor.
2548598-2014-01-20 19:45:12,795::INFO::[_cplogging:55] [20/Jan/2014:19:45:12] ENGINE Bus STOPPED
2548687-2014-01-20 19:45:12,795::INFO::[_cplogging:55] [20/Jan/2014:19:45:12] ENGINE Bus EXITING
2548776-2014-01-20 19:45:12,795::INFO::[_cplogging:55] [20/Jan/2014:19:45:12] ENGINE Bus EXITED
2548864:2014-01-20 19:45:12,795::ERROR::[sabnzbdplus:1405] Failed to start web-interface: 
2548947-Traceback (most recent call last):
2548982-  File "/usr/bin/sabnzbdplus", line 1397, in main
2549032-    cherrypy.engine.start()
2549060-  File "/usr/share/sabnzbdplus/cherrypy/process/wspbus.py", line 184, in start
2549139-    self.publish('start')
2549165-  File "/usr/share/sabnzbdplus/cherrypy/process/wspbus.py", line 147, in publish
2549246-    output.append(listener(*args, **kwargs))
2549291-  File "/usr/share/sabnzbdplus/cherrypy/_cpserver.py", line 90, in start
2549364-    ServerAdapter.start(self)
2549394-  File "/usr/share/sabnzbdplus/cherrypy/process/servers.py", line 62, in start
2549473-    self.wait()
2549489-  File "/usr/share/sabnzbdplus/cherrypy/process/servers.py", line 97, in wait
2549567-    raise self.interrupt
2549592-error: [Errno 99] Cannot assign requested address
2549642:2014-01-20 19:45:12,797::ERROR::[sabnzbdplus:302] Failed to start web-interface : [Errno 99] Cannot assign requested address
2549767-2014-01-20 19:45:12,797::INFO::[__init__:325] SABnzbd shutting down...
2549838-2014-01-20 19:45:12,798::INFO::[__init__:846] Saving data for bookmarks.sab in /mnt/mythtv/sabnzb/admin/bookmarks.sab
2549956-2014-01-20 19:45:12,805::DEBUG::[__init__:332] Stopping URLGrabber
2550023-2014-01-20 19:45:12,805::INFO::[urlgrabber:70] URLGrabber shutting down
2550095-2014-01-20 19:45:12,805::DEBUG::[__init__:339] Stopping Newzbin-Grabber
2550167-2014-01-20 19:45:12,805::DEBUG::[__init__:346] Stopping dirscanner
2550234-2014-01-20 19:45:12,806::INFO::[__init__:846] Saving data for watched_data.sab in /mnt/mythtv/sabnzb/admin/watched_data.sab
2550358-2014-01-20 19:45:12,806::INFO::[dirscanner:254] Dirscanner shutting down
2550431-2014-01-20 19:45:12,806::DEBUG::[__init__:355] Stopping downloader
2550498-2014-01-20 19:45:12,807::DEBUG::[__init__:358] Stopping assembler

[sander]

What's your local IP address? 192.168.1.102, or something else?

[milomak]

local ip is 192.168.1.102 and sabnzb is on port 8080

after it gave that error, I ran /etc/init.d/sabnzbdplus start manually and it worked - related log - http://pastebin.com/ZeMmipE6

full log when error happened - http://pastebin.com/e9P3wKZq

[sander]

"sabnzbdplus-0.6.15 "? Can you first upgrade to the current SAB 0.7.16? It's in the PPA, which you can use for Debian too.

[milomak]

the problems started when i was running 0.7.16-1 and so i downgraded in the hope it would help.

edit - i'll upgrade anyway

[sander]

Does the problem only occur after a fresh start of the system (or reloading of the network)? If so my hypothesis / long shot is (so: to verify): there is not yet an IP address at the moment SAB is started.

Ways to verify:
- set the SAB listening host to 127.0.0.1 or localhost. My assumption is that 127.0.0.1 is there already
- start the service from cron / crontab with a delay. So something like "@reboot /bin/sleep 60 ; /path/to/your/your_program"
- put something in SABnzbd.py to logging.info the ifconfig (or the local LAN IP address) before the webserver is started

[milomak]

unfortunately it drops at any time.

of late i have noticed an increase in the failure rate of downloads (using astraweb and supernews). CRC errors or out of server retention for what is well within the 1000 day threshold or whatever.this could be a seperate issue related to sources i use. but the problems do seem to have started around the same time so it is difficult not to think at the back of my mind that they are related.

[sander]

OK, are you able to handle this: put some extra logging commands in the sab python file?

If so:
- find the correct sab python file. I think it is /usr/bin/sabnzbdplus
- make a copy of it
- as root open the file for editing. Find the line " logging.info('Arguments = %s', sabnzbd.CMDLINE)"
- after that line, add this:

Code: Select all

    try:
        s_ipv4 = socket.socket(socket.AF_INET, socket.SOCK_DGRAM)
        s_ipv4.connect(("www.sabnzbd.org",80))
        logging.info('IP address = %s', s_ipv4.getsockname()[0])
        s_ipv4.close()
    except:
        logging.info('could not determine IP address')
        pass

Please take care of the correct indention! Compare with the code around
Save and exit.

Stop sabnzbd and start it again. Check the sabnzbd.log that it contains the line "IP address":

Code: Select all

grep -i "ip address" ~/.sabnzbd/logs/sabnzbd.log

It should be something like:

Code: Select all

2014-01-20 21:09:23,989::INFO::[SABnzbd:1272] IP address = 192.168.0.105

or

Code: Select all

2014-01-20 21:19:43,877::INFO::[SABnzbd:1275] could not determine IP address

Report back the result here.

[milomak]

here it is

Code: Select all

$ grep -i "ip address" /mnt/mythtv/sabnzb/logs/sabnzbd.log
2014-01-21 19:34:28,339::INFO::[sabnzbdplus:1269] IP address = 192.168.1.102
2014-01-21 19:35:12,886::INFO::[sabnzbdplus:1269] IP address = 192.168.1.102

[sander]

here it is

Code: Select all

$ grep -i "ip address" /mnt/mythtv/sabnzb/logs/sabnzbd.log
2014-01-21 19:34:28,339::INFO::[sabnzbdplus:1269] IP address = 192.168.1.102
2014-01-21 19:35:12,886::INFO::[sabnzbdplus:1269] IP address = 192.168.1.102

... and then it crashes? Or in this case it keeps running?

[sander]

And? What is the answer?