search

sabnzbd / sabnzbd

SABnzbd - The automated Usenet download tool
http://sabnzbd.org
Other
2.25k stars 338 forks source link

systemd failures causing long reboot times and killing of the sabnzbd service #992

Closed kris-anderson closed 7 years ago

kris-anderson commented 7 years ago

I'm on a fresh install of Sabnzbd on CentOS 7 and have the daemon running under systemd. It auto starts and seems to be running fine.

However, I noticed I had some pretty long reboot times on the server, and I traced this back to the systemd sabnzbd service.

It takes 90 seconds to reboot... so I ran the following:

[root@sabnzbd ~]# time systemctl restart sabnzbd

real    1m30.488s
user    0m0.004s
sys 0m0.008s

Looking through the logs, I can see the following:

Aug 06 15:01:27 sabnzbd systemd[1]: Stopping SABnzbd binary newsreader...
Aug 06 15:02:57 sabnzbd systemd[1]: sabnzbd.service stop-sigterm timed out. Killing.
Aug 06 15:02:57 sabnzbd systemd[1]: sabnzbd.service: main process exited, code=killed, status=9/KILL
Aug 06 15:02:57 sabnzbd systemd[1]: Unit sabnzbd.service entered failed state.
Aug 06 15:02:57 sabnzbd systemd[1]: sabnzbd.service failed.

So it appears systemd is unable to stop and restart the service, so it times out after 90 seconds and kills it.

Is there anything I can do to get this working faster? And more ideally, gracefully stopping the Sabnzbd service?

I've tried a number of different configurations for the sabnzbd.service file, but none seemed to make a difference. Here is what I'm using currently:

[Unit]
Description=SABnzbd binary newsreader
Wants=network-online.target
After=network-online.target

[Service]
Type=forking
User=sabnzbd
Group=sabnzbd
ExecStart=/bin/python /opt/sabnzbd/SABnzbd.py --daemon --config-file=/opt/sabnzbd/sabnzbd_config.ini -s 0.0.0.0
GuessMainPID=no
Restart=on-failure

[Install]
WantedBy=multi-user.target
thezoggy commented 7 years ago

what do sab logs show (debug level) when your trying to restart

kris-anderson commented 7 years ago

Thank you for taking the time to help me out thezggy.

I cleared the logs and then ran systemctl restart sabnzbd. Here is the output from the logs:

2017-08-06 16:19:39,581::INFO::[SABnzbd:1170] --------------------------------
2017-08-06 16:19:39,581::INFO::[SABnzbd:1171] SABnzbd.py-2.1.0 (rev=443efb5eda00e165e7d0459824989a6300ec458c)
2017-08-06 16:19:39,581::INFO::[SABnzbd:1172] Full executable path = /opt/sabnzbd/SABnzbd.py
2017-08-06 16:19:39,581::INFO::[SABnzbd:1184] Platform = posix
2017-08-06 16:19:39,581::INFO::[SABnzbd:1185] Python-version = 2.7.5 (default, Nov  6 2016, 00:28:07)
[GCC 4.8.5 20150623 (Red Hat 4.8.5-11)]
2017-08-06 16:19:39,581::INFO::[SABnzbd:1186] Arguments = /opt/sabnzbd/SABnzbd.py --logging 1 --browser 0 --config-file=/opt/sabnzbd/sabnzbd_config.ini
2017-08-06 16:19:39,581::INFO::[SABnzbd:1191] Preferred encoding = UTF-8
2017-08-06 16:19:39,581::INFO::[SABnzbd:1232] Read INI file /opt/sabnzbd/sabnzbd_config.ini
2017-08-06 16:19:39,582::INFO::[__init__:989] Loading data for rss_data.sab from /opt/sabnzbd/admin/rss_data.sab
2017-08-06 16:19:39,583::INFO::[__init__:989] Loading data for totals10.sab from /opt/sabnzbd/admin/totals10.sab
2017-08-06 16:19:39,583::INFO::[postproc:95] Loading postproc queue
2017-08-06 16:19:39,583::INFO::[__init__:989] Loading data for postproc2.sab from /opt/sabnzbd/admin/postproc2.sab
2017-08-06 16:19:39,583::INFO::[__init__:989] Loading data for queue10.sab from /opt/sabnzbd/admin/queue10.sab
2017-08-06 16:19:39,584::INFO::[__init__:989] Loading data for watched_data2.sab from /opt/sabnzbd/admin/watched_data2.sab
2017-08-06 16:19:39,584::INFO::[__init__:989] Loading data for Rating.sab from /opt/sabnzbd/admin/Rating.sab
2017-08-06 16:19:39,584::INFO::[__init__:992] /opt/sabnzbd/admin/Rating.sab missing
2017-08-06 16:19:39,584::INFO::[scheduler:197] Setting schedule for midnight BPS reset
2017-08-06 16:19:39,592::INFO::[__init__:345] All processes started
2017-08-06 16:19:39,593::INFO::[SABnzbd:283] Web dir is /opt/sabnzbd/interfaces/Glitter
2017-08-06 16:19:39,593::INFO::[SABnzbd:283] Web dir is /opt/sabnzbd/interfaces/Config
2017-08-06 16:19:39,610::INFO::[SABnzbd:407] SABYenc module (v3.0.2)... found!
2017-08-06 16:19:39,610::INFO::[SABnzbd:424] Cryptography module (v2.0.3)... found!
2017-08-06 16:19:39,610::INFO::[SABnzbd:429] par2 binary... found (/usr/bin/par2)
2017-08-06 16:19:39,610::INFO::[SABnzbd:434] par2cmdline binary... found (/usr/bin/par2)
2017-08-06 16:19:39,611::INFO::[SABnzbd:440] UNRAR binary... found (/usr/bin/unrar)
2017-08-06 16:19:39,611::INFO::[SABnzbd:453] unzip binary... found (/usr/bin/unzip)
2017-08-06 16:19:39,611::INFO::[SABnzbd:458] 7za binary... found (/usr/bin/7za)
2017-08-06 16:19:39,611::INFO::[SABnzbd:464] nice binary... found (/usr/bin/nice)
2017-08-06 16:19:39,611::INFO::[SABnzbd:468] ionice binary... found (/usr/bin/ionice)
2017-08-06 16:19:39,611::INFO::[SABnzbd:1277] SSL version OpenSSL 1.0.1e-fips 11 Feb 2013
2017-08-06 16:19:39,611::INFO::[SABnzbd:1278] SSL supported protocols ['TLS v1.2', 'TLS v1.1', 'TLS v1', 'SSL v3', 'SSL v2']
2017-08-06 16:19:39,612::INFO::[SABnzbd:1389] Starting web-interface on 0.0.0.0:8080
2017-08-06 16:19:39,612::INFO::[_cplogging:219] [06/Aug/2017:16:19:39] ENGINE Bus STARTING
2017-08-06 16:19:39,614::INFO::[_cplogging:219] [06/Aug/2017:16:19:39] ENGINE Started monitor thread '_TimeoutMonitor'.
2017-08-06 16:19:39,719::INFO::[_cplogging:219] [06/Aug/2017:16:19:39] ENGINE Serving on http://0.0.0.0:8080
2017-08-06 16:19:39,719::INFO::[_cplogging:219] [06/Aug/2017:16:19:39] ENGINE Bus STARTED
2017-08-06 16:19:39,719::INFO::[zconfig:64] No Bonjour/ZeroConfig support installed
2017-08-06 16:19:39,720::INFO::[SABnzbd:1427] Starting SABnzbd.py-2.1.0
2017-08-06 16:19:39,724::INFO::[dirscanner:316] Dirscanner starting up
2017-08-06 16:19:39,725::INFO::[urlgrabber:72] URLGrabber starting up
2017-08-06 16:19:39,727::INFO::[postproc:176] Completed Download Folder /mnt/unraid/Downloads is not on FAT
kris-anderson commented 7 years ago

Here's something interesting... I can restart from the GUI without any issues, but if I attempt to shut down via the GUI I get the following:

500 Internal Server Error

The server encountered an unexpected condition which prevented it from fulfilling the request.

Traceback (most recent call last):
  File "/opt/sabnzbd/cherrypy/_cprequest.py", line 670, in respond
    response.body = self.handler()
  File "/opt/sabnzbd/cherrypy/lib/encoding.py", line 220, in __call__
    self.body = self.oldhandler(*args, **kwargs)
  File "/opt/sabnzbd/cherrypy/_cpdispatch.py", line 60, in __call__
    return self.callable(*self.args, **self.kwargs)
  File "/opt/sabnzbd/sabnzbd/interface.py", line 440, in shutdown
    sabnzbd.halt()
  File "/opt/sabnzbd/sabnzbd/decorators.py", line 32, in newFunction
    return f(*args, **kw)
  File "/opt/sabnzbd/sabnzbd/__init__.py", line 415, in halt
    sabnzbd.downloader.stop()
  File "/opt/sabnzbd/sabnzbd/downloader.py", line 925, in stop
    Downloader.do.stop()
  File "/opt/sabnzbd/sabnzbd/downloader.py", line 919, in stop
    notifier.send_notification("SABnzbd", T('Shutting down'), 'startup')
  File "/opt/sabnzbd/sabnzbd/notifier.py", line 179, in send_notification
    send_notify_osd(title, msg)
  File "/opt/sabnzbd/sabnzbd/notifier.py", line 326, in send_notify_osd
    _NTFOSD = _NTFOSD or pynotify.init('icon-summary-body')
AttributeError: 'module' object has no attribute 'init'
Powered by CherryPy 8.1.2
kris-anderson commented 7 years ago

Based on the error above it looked like an issue with notifications. I disabled NotifyOSD and now shutdown from the GUI is working.

I also made some progress on the systemd side of things by removing this line: Restart=on-failure

By removing that it appears I can stop and restart within a second or so.

Here is my current sabnzbd.service file: `[Unit] Description=SABnzbd binary newsreader Wants=network-online.target After=network-online.target

[Service] ExecStart=/bin/python /opt/sabnzbd/SABnzbd.py --logging 1 --browser 0 --config-file=/opt/sabnzbd/sabnzbd_config.ini Type=simple User=sabnzbd

[Install] WantedBy=multi-user.target`

thezoggy commented 7 years ago

one thing that stood out is how old your python version is, Python-version = 2.7.5 you really should upgrade that to 2.7.13 (latest in 2.7.x) because openssl is part of it which is why yours is currently OpenSSL 1.0.1e-fips 11 Feb 2013. also there have been plenty of bugfixes and performance increases in newer versions.

about your shutdown issue, NTFOSD == NotifyOSD, so check to see what thats failing and disable it if you dont need it.

thezoggy commented 7 years ago

https://www.freedesktop.org/software/systemd/man/systemd.service.html#Restart=

can you try changing restart to: Restart=always

see if that solves your issue

kris-anderson commented 7 years ago

Thank you again thezoggy!

Restart=always

That seems to work! That, or not having the restart command both work. But including this Restart=on-failure seems to be the cause of the systemctl issues.

I did get python 2.7.13 installed and running on this server and Sabnzbd is now reporting that as the version it's using. However, when I shutdown via the GUI with the NotifyOSD box checked, I continue to get the error I mentioned previously. I'm still getting this 500 error:

500 Internal Server Error

The server encountered an unexpected condition which prevented it from fulfilling the request.

Traceback (most recent call last):
  File "/opt/sabnzbd/cherrypy/_cprequest.py", line 670, in respond
    response.body = self.handler()
  File "/opt/sabnzbd/cherrypy/lib/encoding.py", line 220, in __call__
    self.body = self.oldhandler(*args, **kwargs)
  File "/opt/sabnzbd/cherrypy/_cpdispatch.py", line 60, in __call__
    return self.callable(*self.args, **self.kwargs)
  File "/opt/sabnzbd/sabnzbd/interface.py", line 440, in shutdown
    sabnzbd.halt()
  File "/opt/sabnzbd/sabnzbd/decorators.py", line 32, in newFunction
    return f(*args, **kw)
  File "/opt/sabnzbd/sabnzbd/__init__.py", line 415, in halt
    sabnzbd.downloader.stop()
  File "/opt/sabnzbd/sabnzbd/downloader.py", line 925, in stop
    Downloader.do.stop()
  File "/opt/sabnzbd/sabnzbd/downloader.py", line 919, in stop
    notifier.send_notification("SABnzbd", T('Shutting down'), 'startup')
  File "/opt/sabnzbd/sabnzbd/notifier.py", line 179, in send_notification
    send_notify_osd(title, msg)
  File "/opt/sabnzbd/sabnzbd/notifier.py", line 326, in send_notify_osd
    _NTFOSD = _NTFOSD or pynotify.init('icon-summary-body')
AttributeError: 'module' object has no attribute 'init'

Was that removed in the 2.2 release? I'm running 2.2 on an Ubuntu 14.04 box and I don't even see that option in the settings. I'm running 2.1 on my new CentOS box and it does have the NotifyOSD option. I can disable this for now, but I'm curious if I'm missing a package of some sort that's causing my error.

I'd be happy to put together my notes and submit a PR on how I got everything working on a CentOS 7 minimal install if you're interested.

Safihre commented 7 years ago

How did you install pynotify? Via pip or your package manager?

kris-anderson commented 7 years ago

I installed via pip. pynotify did not exist in the yum repos.

From a pip freeze: pynotify==0.1.1

I pip installed the following:

pip install --upgrade pip pip install sabyenc --upgrade pip install cryptography --upgrade pip install cheetah --upgrade pip install pynotify --upgrade

I yum installed these:

yum install git par2cmdline python-cheetah p7zip unzip gcc python-feedparser python-pip -y yum install ftp://rpmfind.net/linux/dag/redhat/el7/en/x86_64/dag/RPMS/unrar-5.0.3-1.el7.rf.x86_64.rpm -y

thezoggy commented 7 years ago

curious, why did you not install via ppa or package?

thezoggy commented 7 years ago

per install.txt -- pynotify is supposed to be optional..

https://github.com/sabnzbd/sabnzbd/blob/develop/sabnzbd/cfg.py#L325 looks like we enable it by default for certain os.. which prob isnt the best to do if were not testing/catching for this..

regardless, we need to wrap that notifier in a try/except to catch the error so it doesnt break restarting sab

kris-anderson commented 7 years ago

I figured if I didn't see it in the yum repo the pip repo may satisfy the requirement.

I uninstalled the pip version and ran the following:

yum install notify-python

Now I don't even see the NotifyOSD option under notifications. Is that the expected behavior?

thezoggy commented 7 years ago

If it can't load the module it doesn't show the options...

Safihre commented 7 years ago

I saw on Stackoverflow that specific pip versions of pynotify have this init problem.. But no indication how to fix it.

kris-anderson commented 7 years ago

That makes sense then. notify-python must not be the same as pynotify. Once I:

pip install pynotify

again then the option comes back.

I don't think the pynotify package exists in the yum repos, at least from what I've searched for. I try not to add other RPM's when I can help it just to keep things as clean as possible. I guess for now I'll just pip remove pynotify and not worry about the extra notification option for now.

Safihre commented 7 years ago

There are pre-made repos for CentOS that are kept up to date, as listed on our wiki: https://sabnzbd.org/wiki/installation/install-fedora-centos-rhel