Jamulus server 3.7.0 terminates when started as systemd service when sending SIGUSR2 to toggle recording

[helgeerbe]

Describe the bug
After updating to version 3.7.0 jamulus server is terminating by SIGTERM (15) after recieving SIGUSR2(12) to toggle recording.

Apr 14 12:02:38 jamulus jamulus[26951]: 2021-04-14 12:02:38, 79.202.58.202, connected (1)
Apr 14 12:02:46 jamulus sudo[26959]:    herbe : TTY=pts/1 ; PWD=/etc/systemd/system ; USER=root ; COMMAND=/usr/bin/systemctl kill -s SIGUSR2 jamulus
Apr 14 12:02:46 jamulus sudo[26959]: pam_unix(sudo:session): session opened for user root by herbe(uid=0)
Apr 14 12:02:46 jamulus jamulus[26951]: OnHandledSignal: 12
Apr 14 12:02:46 jamulus jamulus[26951]: Recording state: enabled
Apr 14 12:02:46 jamulus sudo[26959]: pam_unix(sudo:session): session closed for user root
Apr 14 12:02:46 jamulus jamulus[26951]: OnHandledSignal: 15
Apr 14 12:02:46 jamulus jamulus[26951]: Session RPP: "/home/herbe/recordings/Jam-20210414-120246148/Jam-20210414-120246148.rpp"
Apr 14 12:02:46 jamulus jamulus[26951]: Session LOF: "/home/herbe/recordings/Jam-20210414-120246148/Jam-20210414-120246148.lof"
Apr 14 12:02:46 jamulus jamulus[26951]: 2021-04-14 12:02:46,, server idling -------------------------------------
Apr 14 12:02:46 jamulus systemd[1]: jamulus.service: Succeeded.
Apr 14 12:04:22 jamulus sudo[26961]:    herbe : TTY=pts/1 ; PWD=/etc/systemd/system ; USER=root ; COMMAND=/usr/bin/systemctl restart jamulus.service
Apr 14 12:04:22 jamulus sudo[26961]: pam_unix(sudo:session): session opened for user root by herbe(uid=0)
Apr 14 12:04:22 jamulus systemd[1]: Started Jamulus-Server.
Apr 14 12:04:22 jamulus sudo[26961]: pam_unix(sudo:session): session closed for user root
Apr 14 12:04:22 jamulus jamulus[26965]: - using 64 samples frame size mode
Apr 14 12:04:22 jamulus jamulus[26965]: - using multithreading
Apr 14 12:04:22 jamulus jamulus[26965]: - server mode chosen
Apr 14 12:04:22 jamulus jamulus[26965]: - no GUI mode chosen
Apr 14 12:04:22 jamulus jamulus[26965]: - recording directory name: /home/herbe/recordings/
Apr 14 12:04:22 jamulus jamulus[26965]: - recording will not be enabled
Apr 14 12:04:22 jamulus jamulus[26965]: Using "192.168.178.37" as external IP.
Apr 14 12:04:22 jamulus jamulus[26965]: Recording state: disabled
Apr 14 12:04:22 jamulus jamulus[26965]:  *** Jamulus, Version 3.7.0
Apr 14 12:04:22 jamulus jamulus[26965]:  *** Internet Jam Session Software
Apr 14 12:04:22 jamulus jamulus[26965]:  *** Released under the GNU General Public License (GPL)
Apr 14 12:04:22 jamulus jamulus[26965]: 2021-04-14 12:04:22, 79.202.58.202, connected (1)

To Reproduce
Run jamulus 3.7.0 as headless server.

[Unit]
Description=Jamulus-Server
After=network.target

[Service]
Type=simple
User=herbe
Group=jamulus
NoNewPrivileges=true
ProtectSystem=true
ProtectHome=false
Nice=-20
IOSchedulingClass=realtime
IOSchedulingPriority=0
RestartPreventExitStatus=SIGTERM

#### Change this to set genre, location and other parameters.
#### See [Command-Line-Options](Command-Line-Options) ####
#ExecStart=/usr/local/bin/Jamulus -F -T -s -n -R "/home/herbe/recordings/"
#ExecStart=/usr/local/bin/Jamulus -F -T -s -n -R "/home/herbe/recordings/"
ExecStart=/bin/sh -c '/usr/local/bin/Jamulus -F -T -s -n -R "/home/herbe/recordings/" --norecord'

Restart=on-failure
RestartSec=30
StandardOutput=journal
StandardError=inherit
SyslogIdentifier=jamulus

[Install]
WantedBy=multi-user.target

Send command to toggle recording sudo systemctl kill -s SIGUSR2 jamulus

The recording starts, but after 30 sec the services restarts and all clients are disconnected.

Expected behavior
Same behavior as before the update. Sending SIGUSR2toggles Recording on and off. But does not terminate the system.
Running jamulus 3.7.0 from console works fine. SIGUSR2 works as expected.

Screenshots
See log above.

Operating system
Linux jamulus 5.8.0-45-lowlatency #51-Ubuntu SMP PREEMPT Fri Feb 19 15:11:12 UTC 2021 x86_64 x86_64 x86_64 GNU/Linux

Same failure on self compiled headless binary or using ubuntu .deb package.

Version of Jamulus
3.7.0.
Previous version was not affected.

Additional context

[dcorson-ticino-com]

What happens if you start recording from the command line?
It is strange that it works for 30 seconds and then fails.
Could it be that there is another reason, disk full, for example?
Of course that shouldn't cause a crash, but there are several edge cases with recording that cause errors that are planned to be fixed in the next version. They are not new to 3.7.0 however.

[helgeerbe]

No, there isn't a crash. Jamulus is terminated (or restarted by systemd). Running from command line works fine. If I send SIGUSR2 to the PID, jamulus toggles the recording on and off.
Even when I run it as systemd service I see, that sending SIGUSR2 is toggleing the recording.

But in journalctlI see a following Apr 14 12:02:46 jamulus jamulus[26951]: OnHandledSignal: 15. Wich I interprete as SIGTERM. So following the restart rules, systemd is restarting the service. Maybe I'm wrong. But does jamulus make use of signals internally?

[helgeerbe]

Running df -h looks good to me

Filesystem                         Size  Used Avail Use% Mounted on
tmpfs                              795M  3.7M  792M   1% /run
/dev/mapper/ubuntu--vg-ubuntu--lv  196G   11G  176G   6% /
tmpfs                              3.9G     0  3.9G   0% /dev/shm
tmpfs                              5.0M     0  5.0M   0% /run/lock
tmpfs                              4.0M     0  4.0M   0% /sys/fs/cgroup
/dev/sda2                          976M  619M  290M  69% /boot
tmpfs                              795M   40K  795M   1% /run/user/1000

[helgeerbe]

OK, found root cause.

To handle SIGUSR2properly you must not start jamulus via sh -c

So ExecStart=/usr/local/bin/Jamulus -F -T -s -n -R "/home/herbe/recordings/" works, while ExecStart=/bin/sh -c '/usr/local/bin/Jamulus -F -T -s -n -R "/home/herbe/recordings/" --norecord' fails.

For me it appears that the shell itself is raising the SIGTERM signal.

So in my point of view, your in the .deb package provided systemd file /lib/systemd/system/jamulus-headless.service will always fail to handle SIGUSR2 correctly.

As a workaround you have to start jamulus directly, but you will loose the output in journalctl log.

If you can confirm this. You should change jamulus/distributions/debian/jamulus-headless.service

[hoffie]

Thanks for opening this issue and doing the analysis!

At first glance, I am too wondering why ExecStart is wrapped in sh here as it seems that no shell functions are used.
Nevertheless, I don't understand yet why this should matter either for signal or stdout/stderr handling.

I think we should provide a way which both works regarding signal handling and regarding logging. If this requires changes to the unit file, those should get implemented.

Do you have any idea regarding the logging issue?

[helgeerbe]

I did a clean setup for the service file and logging is working fine for journalctl. Don't know what happend.

Running jamulus from command line: /bin/sh -c '/usr/local/bin/Jamulus -F -T -s -n -R "/home/herbe/recordings/" --norecord' results in 2 processes.

herbe      28765  0.0  0.0   2596   752 pts/1    S+   16:53   0:00 /bin/sh -c /usr/local/bin/Jamulus -F -T -s -n -R "/home/herbe/recordings/" --norecord
herbe      28766 18.3  0.6 535884 51956 pts/1    Sl+  16:53   0:35 /usr/local/bin/Jamulus -F -T -s -n -R /home/herbe/recordings/ --norecord

Sending sudo kill -12 28765 to the shell process, terminates the shell process. Jamulus is still running.

I can only assume, that systemd is terminating all spawn processes, if the master process terminates.

[softins]

The /bin/sh -c is useful if there is a need to substitute environment variables. However, the current example is wrong, as it does indeed result in nested processes.

What is needed is to use exec, for example:

ExecStart=/bin/sh -c 'exec /usr/local/bin/Jamulus -F -T -s -n -R "/home/herbe/recordings/" --norecord'

[helgeerbe]

@softins This works 👍 But I always thought, that sh -c is always using exec(). So the command should run in the process of the shell. This seems not to be true.

[gilgongo]

That's the first time I've seen the use of sh -c in a systemd unit file. Maybe it's because systemd does something odd with it?

[helgeerbe]

You should change jamulus/distributions/debian/jamulus-headless.service and your doc.

[gilgongo]

Sorry can you explain?

[helgeerbe]

You are providing in your .deb package a systemd service file. jamulus/distributions/debian/jamulus-headless.service. This file will fail, if you are using SIGUSR2 to toggle recording on or off.

As @softins pointed out above. exec has to be used to start jamulus in the ExecStart= line, if you want to use sh -c.

In your documentation, you are providing an example file, which starts jamulus directly. Which works fine, but differs from the provided file which make use of sh -c This inconsistent.

[gilgongo]

OK. Since we've not had anyone report any problem with the Exec line without sh -c in the last 18 months, we can assume it's not needed in our supported platforms, so we can simply remove it from jamulus-headless.service I think.

[hoffie]

git blame shows the likely reason for it being this way: The line did contain shell substitution logic in the past (18d06b9), but it has been removed meanwhile (50fb76c).

cc @tormodvolden @ann0see

[softins]

I am preparing a PR to fix this properly, by using sh -c 'exec /usr/bin/jamulus-headless ....'

[helgeerbe]

@softins I did an additional test. If you are going to use bash -c you don't need the exec command. With -c bash uses exec() and sh is using fork() to start a command.