"Lost Connection," Signal 15 & Restart

[commiepinko]

I'm running Sabnzbd v4.4.1 under Docker v20.10.23 on a Synology DS920+ running DSM v7.2.2. The relevant Docker Compose service is:

Code: Select all

  sabnzbd:
    image: sabnzbd:latest
    container_name: sabnzbd
    restart: unless-stopped
    network_mode: "service:vpn"
    depends_on:
      vpn:
        condition: service_healthy
    volumes:
      - ${CONFIG_ROOT}/sabnzbd:/config
      - ${SERVER_ROOT}/downloads/usenet:/server/downloads/usenet
    environment:
      - PUID=${USER_ID}
      - PGID=${GROUP_ID}
      - TZ=${TIMEZONE}
      - LOG_LEVEL=debug
    healthcheck:
      test: [ "CMD", "curl", "--fail", "http://127.0.0.1:${SABNZBD_UI_PORT}/sabnzbd/ping" ]
      interval: ${INTERVAL}
      retries: ${RETRIES}

Every few minutes, Sabnzbd restarts for no apparent reason. Log entries are as follows:

Code: Select all

2025-01-28 19:47:55,060::INFO::[notifier:157] Sending notification: Warning - Signal 15 caught, saving and exiting... (type=warning, job_cat=None)
2025-01-28 19:47:55,060::WARNING::[__init__:199] Signal 15 caught, saving and exiting...
2025-01-28 19:47:55,061::INFO::[__init__:416] [N/A] Performing SABnzbd shutdown
2025-01-28 19:47:55,061::INFO::[__init__:333] SABnzbd shutting down...
2025-01-28 19:47:55,061::INFO::[ssdp:102] Stopping SSDP
2025-01-28 19:47:55,063::INFO::[directunpacker:561] Aborting all DirectUnpackers
2025-01-28 19:47:55,064::INFO::[notifier:157] Sending notification: SABnzbd - Shutting down (type=startup, job_cat=None)
2025-01-28 19:47:55,065::INFO::[downloader:643] Shutting down
2025-01-28 19:47:55,066::INFO::[nzbqueue:230] Saving queue
2025-01-28 19:47:55,067::INFO::[postproc:138] Saving postproc queue
2025-01-28 19:47:55,068::INFO::[__init__:402] All processes stopped
2025-01-28 19:47:55,071::INFO::[_cplogging:213] [28/Jan/2025:19:47:55] ENGINE Bus STOPPING
2025-01-28 19:47:55,542::INFO::[_cplogging:213] [28/Jan/2025:19:47:55] ENGINE HTTP Server cherrypy._cpwsgi_server.CPWSGIServer(('::', 5243)) shut down
2025-01-28 19:47:55,542::INFO::[_cplogging:213] [28/Jan/2025:19:47:55] ENGINE Bus STOPPED
2025-01-28 19:47:55,543::INFO::[_cplogging:213] [28/Jan/2025:19:47:55] ENGINE Bus EXITING
2025-01-28 19:47:55,543::INFO::[_cplogging:213] [28/Jan/2025:19:47:55] ENGINE Bus EXITED
2025-01-28 19:47:55,543::INFO::[notifier:157] Sending notification: SABnzbd - SABnzbd shutdown finished (type=startup, job_cat=None)
2025-01-28 19:47:55,543::INFO::[SABnzbd:1579] Leaving SABnzbd
2025-01-28 19:48:09,546::INFO::[SABnzbd:1142] --------------------------------
2025-01-28 19:48:09,562::INFO::[SABnzbd:1143] SABnzbd[dot]py-4.4.1

2025-01-28 19:48:09,562::INFO::[SABnzbd:1153] Commit = d897936da564ee5564a697dfcfd5eec5824b0d0c
2025-01-28 19:48:09,563::INFO::[SABnzbd:1155] Full executable path = /app/sabnzbd/SABnzbd[dot]py
2025-01-28 19:48:09,563::INFO::[SABnzbd:1156] Arguments = "/app/sabnzbd/SABnzbd[dot]py" "--config-file" "/config" "--server" "::"
2025-01-28 19:48:09,563::INFO::[SABnzbd:1157] Python-version = 3.12.8 (main, Dec  7 2024, 05:56:13) [GCC 14.2.0]
2025-01-28 19:48:09,563::INFO::[SABnzbd:1158] Dockerized = True

2025-01-28 19:48:09,563::INFO::[SABnzbd:1159] CPU architecture = x86_64
2025-01-28 19:48:09,567::INFO::[SABnzbd:1162] Platform = posix - Linux-4.4.302+-x86_64-with
2025-01-28 19:48:09,568::INFO::[SABnzbd:1168] Preferred encoding = UTF-8
2025-01-28 19:48:09,568::INFO::[SABnzbd:1190] SSL version = OpenSSL 3.3.2 3 Sep 2024
2025-01-28 19:48:09,569::INFO::[SABnzbd:1199] Certifi version = 2024.08.30
2025-01-28 19:48:09,570::INFO::[SABnzbd:1200] Loaded additional certificates from /lsiopy/lib/python3.12/site-packages/certifi/cacert.pem
2025-01-28 19:48:09,570::INFO::[SABnzbd:1210] Using INI file /config/sabnzbd.ini
2025-01-28 19:48:09,571::INFO::[postproc:143] Loading postproc queue
2025-01-28 19:48:09,572::INFO::[scheduler:190] Scheduling RSS interval task every 60 min (delay=52)
2025-01-28 19:48:09,572::INFO::[scheduler:215] Setting schedule for midnight auto history-purge
2025-01-28 19:48:09,573::INFO::[scheduler:224] Setting schedule for midnight BPS reset
2025-01-28 19:48:09,573::INFO::[scheduler:233] Setting schedule for midnight server expiration check
2025-01-28 19:48:09,573::INFO::[scheduler:242] Setting schedule for server quota check
2025-01-28 19:48:09,573::INFO::[__init__:303] All processes started
2025-01-28 19:48:09,573::INFO::[SABnzbd:340] Template location for Glitter is /app/sabnzbd/interfaces/Glitter
2025-01-28 19:48:09,573::INFO::[SABnzbd:340] Template location for Config is /app/sabnzbd/interfaces/Config
2025-01-28 19:48:09,574::INFO::[misc:1260] [N/A] Running external command: ['/usr/bin/unrar']
2025-01-28 19:48:09,580::INFO::[misc:1260] [N/A] Running external command: ['/usr/bin/7zz']
2025-01-28 19:48:09,585::INFO::[misc:1260] [N/A] Running external command: ['/usr/local/bin/par2', '-V']
2025-01-28 19:48:09,588::INFO::[SABnzbd:425] SABCTools module (v8.2.5)... found!
2025-01-28 19:48:09,588::INFO::[SABnzbd:426] SABCTools module is using SIMD set: SSSE3
2025-01-28 19:48:09,588::INFO::[SABnzbd:427] SABCTools module is linked to OpenSSL: True
2025-01-28 19:48:09,588::INFO::[SABnzbd:447] Cryptography module (v44.0.0)... found!
2025-01-28 19:48:09,589::INFO::[SABnzbd:453] par2 binary... found (/usr/local/bin/par2)
2025-01-28 19:48:09,589::INFO::[SABnzbd:460] UNRAR binary... found (/usr/bin/unrar)
2025-01-28 19:48:09,589::INFO::[SABnzbd:468] UNRAR binary version 7.01
2025-01-28 19:48:09,589::INFO::[SABnzbd:475] 7za binary... found (/usr/bin/7zz)
2025-01-28 19:48:09,589::INFO::[SABnzbd:477] 7za binary version 24.08
2025-01-28 19:48:09,589::INFO::[SABnzbd:483] nice binary... found (/bin/nice)
2025-01-28 19:48:09,589::INFO::[SABnzbd:487] ionice binary... found (/bin/ionice)
2025-01-28 19:48:09,590::INFO::[SABnzbd:1404] Starting web-interface on :::5243
2025-01-28 19:48:09,591::INFO::[_cplogging:213] [28/Jan/2025:19:48:09] ENGINE Bus STARTING
2025-01-28 19:48:14,717::INFO::[_cplogging:213] [28/Jan/2025:19:48:14] ENGINE Serving on h t t p://:::5243
2025-01-28 19:48:14,717::INFO::[_cplogging:213] [28/Jan/2025:19:48:14] ENGINE Bus STARTED
2025-01-28 19:48:14,717::INFO::[SABnzbd:1443] Starting SABnzbd[dot]py-4.4.1
2025-01-28 19:48:14,719::INFO::[dirscanner:112] Dirscanner starting up
2025-01-28 19:48:14,720::INFO::[notifier:157] Sending notification: SABnzbd - SABnzbd 4.4.1 started (type=startup, job_cat=None)
2025-01-28 19:48:14,721::INFO::[zconfig:61] No bonjour/zeroconf support installed
2025-01-28 19:48:14,722::INFO::[ssdp:108] Serving SSDP on 10.5.251.195 as SABnzbd

[RINSE, REPEAT]

Other than that, my entire setup runs flawlessly. I've rebuilt everything from scratch several times to no avail. I'm at a loss.

[sander]

Have you googled "signal 15" and "signal 15 sabnzbd"? It's a vague thing because the receiving process (SABnzbd) cannot see which process sent the signal 15.

You know it means some other process sent that signal 15 = SIGTERM to SABnzbd?

The great thing: with bpftrace -> killsnoop you can find the sending process

Proof:

I started sabnzbd and killed it from a bash shell:

Code: Select all

sander@zwarte:~$ ps -ef | grep -i sabnzbd
sander     54360   51743 28 07:44 pts/0    00:00:04 /usr/bin/python3 -OO /usr/bin/sabnzbdplus
sander     54502   54446  0 07:44 pts/3    00:00:00 grep --color=auto -i sabnzbd

sander@zwarte:~$ kill -15 54360

... and killsnoop tells it was bash that sent the signal 15:

Code: Select all

$ sudo /usr/sbin/killsnoop.bt
Attaching 3 probes...
Tracing kill() signals... Hit Ctrl-C to end.
TIME                PID COMM              SIG   TPID RESULT
07:44:01.508564    6907 chrome              9  15153      0
07:44:30.862180   54446 bash               15  54360      0
07:45:01.320862     330 systemd-journal     0    447      0

So that way you can at least find which process is sending the Signal 15 to SABnzbd.

[sander]

Ah, this is nice, although not useful for you (unless you know how to edit a file within a docker container ... do you know)

Start python, and send signal 15 from bash ... terminated:

Code: Select all

sander@zwarte:~$ python3
Python 3.12.3 (main, Jan 17 2025, 18:03:48) [GCC 13.3.0] on linux
Type "help", "copyright", "credits" or "license" for more information.
>>> Terminated

But: Start python, ignore the signal, and send signal 15 from bash ... NOT terminated:

Code: Select all

sander@zwarte:~$ python3
Python 3.12.3 (main, Jan 17 2025, 18:03:48) [GCC 13.3.0] on linux
Type "help", "copyright", "credits" or "license" for more information.
>>> import signal
>>> signal.signal(signal.SIGTERM, signal.SIG_IGN)
<Handlers.SIG_DFL: 0>
>>> 
>>>

And the good news: SABnzbd already uses signal

Code: Select all

$ grep -irn signal SABnzbd.py 
33:import signal
125:# Global for this module, signaling loglevel change
375:            # Ignore Win32 "logoff" signal
377:            # Instead the signal_handler will ignore the "logoff" signal
378:            # signal.signal(5, signal.SIG_IGN)
1624:    signal.signal(signal.SIGINT, sabnzbd.sig_handler)
1625:    signal.signal(signal.SIGTERM, sabnzbd.sig_handler)

and

Code: Select all

$ grep -irn sig_handler *
sabnzbd/__init__.py:197:def sig_handler(signum=None, frame=None):
SABnzbd.py:119:    win32api.SetConsoleCtrlHandler(sabnzbd.sig_handler, True)
SABnzbd.py:1624:    signal.signal(signal.SIGINT, sabnzbd.sig_handler)
SABnzbd.py:1625:    signal.signal(signal.SIGTERM, sabnzbd.sig_handler)

So ... brute force we could ignore Signal 15. Although I have no idea of bad consequences.

[commiepinko]

You know it means some other process sent that signal 15 = SIGTERM to SABnzbd?

I do.

The great thing: with bpftrace -> killsnoop you can find the sending process

Brilliant. Unfortunately, the Docker version (20.10.23) installed with Synology DSM 7.2.2 doesn't support cap-add PERFMON or BPF, which is (so far as I can figure) my only option for installing killall. Feh.

Ah, this is nice, although not useful for you (unless you know how to edit a file within a docker container ... do you know)

I do.

So ... brute force we could ignore Signal 15. Although I have no idea of bad consequences.

Knowing zilch python, I've made a wild guess at how one might do that and committed the following likely atrocity.

Code: Select all

#     signal.signal(signal.SIGINT, sabnzbd.sig_handler)
#     signal.signal(signal.SIGTERM, sabnzbd.sig_handler)

The result is, alas, no change, but it's likely my implementation of your suggestion is idiotic.

[jcfp]

You don't want to ignore signal 15, it's the normal way of telling a process to do a clean shutdown.

What if you ditch that healthcheck thing in the docker compose file? Any other process monitor active?

[sander]

The basics, without Docker:

Code: Select all

$ sed -i -e 's/signal.SIGTERM, sabnzbd.sig_handler/signal.SIGTERM, signal.SIG_IGN/' SABnzbd.py

Check:

Code: Select all

$ cat SABnzbd.py | grep SIGTERM
    signal.signal(signal.SIGTERM, signal.SIG_IGN)

Good.

Starting that SABnzbd.py ... a kill -15 is nicely ignored by SABnzbd.

Next step: Docker. BRB.


FWIW: a kill -9 still nicely kills SABnzbd.

[sander]

Docker:

Code: Select all

docker run -p 8080:8080 -v /home/sander/docker-sabnzbd-config:/config -v /home/sander/docker-sabnzbd-downloads:/downloads  lscr.io/linuxserver/sabnzbd:latest

From another terminal: go into the running Docker container

Code: Select all

docker exec b58140df4bbc -it /bin/bash

root@b58140df4bbc:/# cd /app/sabnzbd/
root@b58140df4bbc:/app/sabnzbd# cat SABnzbd.py | grep SIGTERM
    signal.signal(signal.SIGTERM, sabnzbd.sig_handler)
root@b58140df4bbc:/app/sabnzbd# 
root@b58140df4bbc:/app/sabnzbd# sed -i -e 's/signal.SIGTERM, sabnzbd.sig_handler/signal.SIGTERM, signal.SIG_IGN/' SABnzbd.py
root@b58140df4bbc:/app/sabnzbd# 
root@b58140df4bbc:/app/sabnzbd# cat SABnzbd.py | grep SIGTERM
    signal.signal(signal.SIGTERM, signal.SIG_IGN)

NOW: in SAB-gui, choose "Restart SABnzbd" to make it active

Let's check:

Yet another terminal:

Code: Select all

sander@zwarte:~$ ps -ef | grep -i sabnzbd
sander     63113   51743  0 10:13 pts/0    00:00:00 docker run -p 8080:8080 -v /home/sander/docker-sabnzbd-config:/config -v /home/sander/docker-sabnzbd-downloads:/downloads lscr.io/linuxserver/sabnzbd:latest
root       63235   63185  0 10:13 ?        00:00:00 s6-supervise svc-sabnzbd
911        63344   63235  2 10:13 ?        00:00:05 python3 /app/sabnzbd/SABnzbd.py --config-file /config --server ::
sander     63622   63572  0 10:16 pts/4    00:00:00 grep --color=auto -i sabnzbd
sander@zwarte:~$ 
sander@zwarte:~$ 
sander@zwarte:~$ kill -15 63344
bash: kill: (63344) - Operation not permitted
sander@zwarte:~$ 
sander@zwarte:~$ sudo kill -15 63344
[sudo] password for sander: 
sander@zwarte:~$ 

... and the kill -15 ignored by SABnzbd inside the Docker. Nice!

[sander]

So ... this hack method seems to work. Can you verify?

We might consider developing an option "ignore_sigterm=1" in sabnzbd.ini so the hacking is not needed. I need the advice from Safihre on that.

[safihre]

We can't ignore it. See jcfps comment, this is completely expected behavior to act on it.

We need to find the source of the signal, it's not normal.
This is just acting on the symptoms instead of the source.

[safihre]

The health check you do is on a non existing endpoint. So it probably gives a 400 or 500 error.
So that results in the system thinking Sab is unhealthy and forcing a restart.
You should strip the ping part, just call /sabnzbd
Then it probably works.

[sander]

We can't ignore it. See jcfps comment, this is completely expected behavior to act on it.

I had missed jcfp's post.

Clear.

[commiepinko]

The health check you do is on a non existing endpoint. So it probably gives a 400 or 500 error.
So that results in the system thinking Sab is unhealthy and forcing a restart.
You should strip the ping part, just call /sabnzbd
Then it probably works.

Hah! Right you are. Thanks for pointing out my rookie mistake. Now if I could only figure out how to flag this "Solved. safihre is a God."

[safihre]