Service stops randomly, help me find root cause

[tonypags314]

Hi All,
I recently built a new VM for my SAB instance. It's running great, except every few days or so the service stops for no reason. I found the log, it seems that it's stopping and logging that activity but nothing as to why it's stopping. Then some time later when I noticed it down, I started the service and everything works again.

log snippet:

Code: Select all

2024-02-08 22:18:51,127::INFO::[postproc:129] Saving postproc queue
2024-02-08 22:18:51,128::INFO::[notifier:123] Sending notification: SABnzbd - Queue finished (type=queue_done, job_cat=None)
2024-02-09 21:51:29,027::INFO::[__init__:441] [N/A] Performing SABnzbd shutdown
2024-02-09 21:51:29,027::INFO::[__init__:353] SABnzbd shutting down...
2024-02-09 21:51:29,028::INFO::[directunpacker:542] Aborting all DirectUnpackers
2024-02-09 21:51:29,038::INFO::[notifier:123] Sending notification: SABnzbd - Shutting down (type=startup, job_cat=None)
2024-02-09 21:51:29,039::INFO::[downloader:695] Shutting down
2024-02-09 21:51:29,054::INFO::[nzbqueue:234] Saving queue
2024-02-09 21:51:29,058::INFO::[postproc:129] Saving postproc queue
2024-02-09 21:51:29,061::INFO::[__init__:427] All processes stopped
2024-02-09 21:51:29,063::INFO::[_cplogging:213] [09/Feb/2024:21:51:29] ENGINE Bus STOPPING
2024-02-09 21:51:29,761::INFO::[_cplogging:213] [09/Feb/2024:21:51:29] ENGINE HTTP Server cherrypy._cpwsgi_server.CPWSGIServer(('10.0.0.200', 8080)) shut down
2024-02-09 21:51:29,762::INFO::[_cplogging:213] [09/Feb/2024:21:51:29] ENGINE Bus STOPPED
2024-02-09 21:51:29,762::INFO::[_cplogging:213] [09/Feb/2024:21:51:29] ENGINE Bus EXITING
2024-02-09 21:51:29,763::INFO::[_cplogging:213] [09/Feb/2024:21:51:29] ENGINE Bus EXITED
2024-02-09 21:51:29,766::INFO::[notifier:123] Sending notification: SABnzbd - SABnzbd shutdown finished (type=startup, job_cat=None)
2024-02-09 21:51:29,772::INFO::[sabnzbdplus:1617] Leaving SABnzbd
2024-02-10 10:57:32,418::INFO::[sabnzbdplus:1168] --------------------------------
2024-02-10 10:57:32,418::INFO::[sabnzbdplus:1169] sabnzbdplus-3.7.1
2024-02-10 10:57:32,419::INFO::[sabnzbdplus:1179] Commit = 479daf0e76345bdfa58a8ba8e723aa34602e5035
2024-02-10 10:57:32,419::INFO::[sabnzbdplus:1181] Full executable path = /usr/bin/sabnzbdplus
2024-02-10 10:57:32,419::INFO::[sabnzbdplus:1182] Arguments = "/usr/bin/sabnzbdplus"
2024-02-10 10:57:32,419::INFO::[sabnzbdplus:1183] Python-version = 3.11.2 (main, Mar 13 2023, 12:18:29) [GCC 12.2.0]
2024-02-10 10:57:32,419::INFO::[sabnzbdplus:1184] Dockerized = False
2024-02-10 10:57:32,423::INFO::[sabnzbdplus:1185] CPU architecture = x86_64
2024-02-10 10:57:32,425::INFO::[sabnzbdplus:1188] Platform = posix - Linux-6.1.0-17-amd64-x86_64-with-glibc2.36
2024-02-10 10:57:32,426::INFO::[sabnzbdplus:1194] Preferred encoding = UTF-8
2024-02-10 10:57:32,426::INFO::[sabnzbdplus:1216] SSL version = OpenSSL 3.0.11 19 Sep 2023
2024-02-10 10:57:32,429::INFO::[sabnzbdplus:1225] Certifi version = 2022.09.24
2024-02-10 10:57:32,429::INFO::[sabnzbdplus:1226] Loaded additional certificates from /etc/ssl/certs/ca-certificates.crt
2024-02-10 10:57:32,430::INFO::[sabnzbdplus:1247] Using INI file /home/user/.sabnzbd/sabnzbd.ini

[sander]

Based on what do you say it stops? How/What did you measure?

Also: that logging is just the startup?

[tonypags314]

How do I tell if a service is stopped? I run `systemctl status nameofservice`

Also, that logging is the shutdown entries, with a few lines before to show that it's the first log entry in some time, and I kept the start up entries in there since it's the next entries to show version info, etc.

[sander]

Ah, I was only looking at the last part of the logging!

Instead of a service, run sabnzbd from the CLI, with "-l2" (= +Debug logging). Keep the CLI open, and see what happens.

[safihre]

This is also an old version of Sabnzbd, 3.7.1. We are already at 4.2.2.
What platform are you on?

[tonypags314]

OK. I set option in INI file log_level = 2, restarted service, and confirmed DEBUG entries are being added to log file. I hope that's good enough. Now we wait a few days........

I'm running it on Debian 12. It's the latest version from the repo.

Code: Select all

admin@hostname:~$ sudo apt install sabnzbdplus
Reading package lists... Done
Building dependency tree... Done
Reading state information... Done
sabnzbdplus is already the newest version (3.7.1+dfsg-2).
The following package was automatically installed and is no longer required:
  linux-image-6.1.0-16-amd64
Use 'sudo apt autoremove' to remove it.
0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded.

Your docs say this is old but if I have to wait for your newer version to become available on the repo, so be it.

[sander]

Why do you use Debian?

As it's a VM, how about installing Ubuntu 23.10, which has sabnzbdplus 4.0.2. And upgrading sabnzbd on Ubuntu is easy

SABnzbd on Ubuntu is much easier. And Ubuntu itself is easier than Debian.

[OneCD]

Although, running SABnzbd from source on Debian isn't a big deal. I've been running it that way for quite a while now.

[sander]

Although, running SABnzbd from source on Debian isn't a big deal. I've been running it that way for quite a while now.

Can you guide OP how to do that?

[OneCD]

Can you guide OP how to do that?

Already covered in the wiki: https://sabnzbd.org/wiki/installation/i ... ff-modules

Just need to use the SystemD service file: https://github.com/sabnzbd/sabnzbd/blob ... 40.service

Mine looks like:

Code: Select all

# copy or _hard_link to
#   Debian: /lib/systemd/system/[email protected]
#   others: /usr/lib/systemd/system/[email protected]
#
# To start SABNzbd once for USER use:
#   systemctl start [email protected]
#
# To start SABNzbd on boot for USER use:
#   systemctl enable [email protected]
#
# Config will be placed in ~USER/.sabnzbd/

[Unit]
Description=SABnzbd binary newsreader
Documentation=https://sabnzbd.org/wiki/
Wants=network-online.target
After=network-online.target

[Service]
ExecStart=/opt/sabnzbd.venv/bin/python3 /opt/sabnzbd/SABnzbd.py --browser 0 
User=%I
Type=simple
Restart=on-failure

[Install]
WantedBy=multi-user.target

... and sits in my $HOME.

[tonypags314]

Mine looks like

Code: Select all

[Unit]
Description=SABnzbd binary newsreader
Documentation=https://sabnzbd.org/wiki/
Wants=network-online.target
After=network-online.target

[Service]
Environment="PYTHONIOENCODING=utf-8"
#ExecStart=/opt/sabnzbd/SABnzbd.py --disable-file-log --logging 1 --browser 0
ExecStart=/usr/bin/sabnzbdplus
User=%I
Type=simple
Restart=on-failure

[Install]
WantedBy=multi-user.target

My version of Python 3.11.2

Do I need to run it from source to leverage systemd so it's always running as a service? Maybe because I'm not adding any flags like `--browser 0` it's timing out after a while? Do the same flags apply to the binary? I think my INI disabled the browser using `auto_browser = 0` but not sure.

[OneCD]

Do I need to run it from source to leverage systemd so it's always running as a service?

No, you can run any version this way. The service script is only to manage starting and stopping an application automatically during OS startup and shutdown.

You don't need it however. Just run the SABnzbd executable directly. @sander suggested this earlier.

One variation I would add though is to launch your existing SABnzbd executable in a 'screen' session while you're diagnosing this random quit issue. This way, you can detach from your terminal after you've launched SABnzbd manually, and reconnect to it later (even weeks, months or years later - the 'screen' session remains active until you exit from it or reboot) in the event SABnzbd stops running to see if any stdout or stderr was generated at the time it quit. You can also log everything generated in the 'screen' session, but let's not go there just-yet.

Maybe because I'm not adding any flags like `--browser 0` it's timing out after a while? Do the same flags apply to the binary? I think my INI disabled the browser using `auto_browser = 0` but not sure.

Unimportant. I tell SABnzbd not to launch a browser instance on startup as I'm running SABnzbd via Debian on a headless NAS. It doesn't affect the way SABnzbd runs though.

[tonypags314]

It happened again overnight.

Code: Select all

2024-02-13 02:58:55,426::DEBUG::[interface:133] Request GET /api from [[sonar VM IP]] [Sonarr/3.0.10.1567 (ubuntu 18.04)] {'mode': 'history', 'start': '0', 'limit': '60', 'category': 'tv', 'apikey': 'f0efd3e826c641beab79827f9e54979a', 'output': 'json'}
2024-02-13 02:59:53,071::DEBUG::[interface:133] Request GET /api from [[sonar VM IP]] [Sonarr/3.0.10.1567 (ubuntu 18.04)] {'mode': 'queue', 'start': '0', 'limit': '0', 'apikey': '[[sab api key]]', 'output': 'json'}
2024-02-13 02:59:53,090::DEBUG::[interface:133] Request GET /api from [[sonar VM IP]] [Sonarr/3.0.10.1567 (ubuntu 18.04)] {'mode': 'history', 'start': '0', 'limit': '60', 'category': 'tv', 'apikey': '[[sab api key]]', 'output': 'json'}
2024-02-13 03:00:01,880::DEBUG::[interface:133] Request GET / from [[proxy VM IP]] (X-Forwarded-For: 172.70.66.12) [Cloudflare-SSLDetector] {}
2024-02-13 03:00:01,881::DEBUG::[getperformance:50] CPU model = AMD Opteron(tm) X3421 APU
2024-02-13 03:00:02,093::DEBUG::[interface:133] Request GET / from [[proxy VM IP]] (X-Forwarded-For: [[Cloudflare pub IP]]) [Cloudflare-SSLDetector] {}
2024-02-13 03:00:02,094::DEBUG::[getperformance:50] CPU model = AMD Opteron(tm) X3421 APU
2024-02-13 03:00:02,285::DEBUG::[interface:133] Request GET / from [[proxy VM IP]] (X-Forwarded-For: [[Cloudflare pub IP]]) [Cloudflare-SSLDetector] {}
2024-02-13 03:00:02,287::DEBUG::[getperformance:50] CPU model = AMD Opteron(tm) X3421 APU
2024-02-13 03:00:02,435::DEBUG::[interface:133] Request GET / from [[proxy VM IP]] (X-Forwarded-For: [[Cloudflare pub IPv6]]) [Cloudflare-SSLDetector] {}
2024-02-13 03:00:02,436::DEBUG::[getperformance:50] CPU model = AMD Opteron(tm) X3421 APU
2024-02-13 03:00:02,598::DEBUG::[interface:133] Request GET /robots.txt from [[proxy VM IP]] (X-Forwarded-For: [[Cloudflare pub IP]]) [Cloudflare-SSLDetector] {}
2024-02-13 03:00:02,753::DEBUG::[interface:133] Request GET /robots.txt from [[proxy VM IP]] (X-Forwarded-For: [[Cloudflare pub IP]]) [Cloudflare-SSLDetector] {}
2024-02-13 03:00:02,922::DEBUG::[interface:133] Request GET /robots.txt from [[proxy VM IP]] (X-Forwarded-For: [[Cloudflare pub IP]]) [Cloudflare-SSLDetector] {}
2024-02-13 03:00:03,121::DEBUG::[interface:133] Request GET /robots.txt from [[proxy VM IP]] (X-Forwarded-For: [[Cloudflare pub IPv6]]) [Cloudflare-SSLDetector] {}
2024-02-13 03:00:03,271::DEBUG::[interface:133] Request GET / from [[proxy VM IP]] (X-Forwarded-For: [[Cloudflare pub IPv6]]) [Cloudflare-SSLDetector] {}
2024-02-13 03:00:03,277::DEBUG::[getperformance:50] CPU model = AMD Opteron(tm) X3421 APU
2024-02-13 03:00:03,509::DEBUG::[interface:133] Request GET / from [[proxy VM IP]] (X-Forwarded-For: [[Cloudflare pub IPv6]]) [Cloudflare-SSLDetector] {}
2024-02-13 03:00:03,510::DEBUG::[getperformance:50] CPU model = AMD Opteron(tm) X3421 APU
2024-02-13 03:00:03,837::DEBUG::[interface:133] Request GET / from [[proxy VM IP]] (X-Forwarded-For: [[Cloudflare pub IPv6]]) [Cloudflare-SSLDetector] {}
2024-02-13 03:00:03,838::DEBUG::[getperformance:50] CPU model = AMD Opteron(tm) X3421 APU
2024-02-13 03:00:04,027::DEBUG::[interface:133] Request GET /config/ from [[proxy VM IP]] (X-Forwarded-For: [[Cloudflare pub IP]]) [Cloudflare-SSLDetector] {}
2024-02-13 03:00:04,426::DEBUG::[interface:133] Request GET /config/general/ from [[proxy VM IP]] (X-Forwarded-For: [[Cloudflare pub IPv6]]) [Cloudflare-SSLDetector] {}
2024-02-13 03:00:04,433::DEBUG::[interface:133] Request GET /config/categories/ from [[proxy VM IP]] (X-Forwarded-For: [[Cloudflare pub IP]]) [Cloudflare-SSLDetector] {}
2024-02-13 03:00:04,896::DEBUG::[interface:133] Request GET /shutdown/ from [[proxy VM IP]] (X-Forwarded-For: [[Cloudflare pub IP]]) [Cloudflare-SSLDetector] {'apikey': '[[sab api key]]', 'pid': '234211'}
2024-02-13 03:00:04,899::INFO::[__init__:441] [sabnzbd.interface.shutdown] Performing SABnzbd shutdown
2024-02-13 03:00:04,900::INFO::[__init__:353] SABnzbd shutting down...
2024-02-13 03:00:04,900::INFO::[directunpacker:542] Aborting all DirectUnpackers
2024-02-13 03:00:04,902::DEBUG::[__init__:371] Stopping RSSReader
2024-02-13 03:00:04,903::DEBUG::[__init__:374] Stopping URLGrabber
2024-02-13 03:00:04,905::DEBUG::[__init__:381] Stopping dirscanner
2024-02-13 03:00:04,906::DEBUG::[__init__:388] Stopping downloader
2024-02-13 03:00:04,907::INFO::[notifier:123] Sending notification: SABnzbd - Shutting down (type=startup, job_cat=None)

My proxy VM is a cloudflare tunnel agent. So this is probably some service routing through the internet, not thru my local network. Or maybe a service in my local network is using the domain name of SAB instead of the local IP, and it's getting routed out > CF > and back in.

At 3AM, there was no activity in Sonarr nor in Radarr (my only RSS tools), and I didn't put any NZB files into the watched folder. But something somewhere sent a shutdown request...?

[sander]

At 3AM, there was no activity in Sonarr nor in Radarr (my only RSS tools), and I didn't put any NZB files into the watched folder. But something somewhere sent a shutdown request...?

Exactly:

Code: Select all

2024-02-13 03:00:04,896::DEBUG::[interface:133] Request GET /shutdown/ from [[proxy VM IP]] (X-Forwarded-For: [[Cloudflare pub IP]]) [Cloudflare-SSLDetector] {'apikey': '[[sab api key]]', 'pid': '234211'}

And it has the APIKEY, so you must have allowed it.

So SABnzbd does not stop randomly, but as it is instructed by an authorized client.

If you don't want that and can't solve it, change SAB's api key.

[OneCD]

So SABnzbd does not stop randomly, but as it is instructed by an authorized client.

Nice catch @sander.