DietPi-Software | Radarr: Updating to latest version within the webapp may cause it to fail.

TDuffinNTU commented 1 year ago

Creating a bug report/issue

Required Information

DietPi version | cat /boot/dietpi/.version G_DIETPI_VERSION_CORE=8 G_DIETPI_VERSION_SUB=16 G_DIETPI_VERSION_RC=2 G_GITBRANCH='master' G_GITOWNER='MichaIng'
Distro version | echo $G_DISTRO_NAME $G_RASPBIAN bullseye 0
Kernel version | uname -a Linux DietPi 6.1.21-v8+ #1642 SMP PREEMPT Mon Apr 3 17:24:16 BST 2023 aarch64 GNU/Linux
SBC model | echo $G_HW_MODEL_NAME or (EG: RPi3) RPi 4 Model B (aarch64)
Power supply used | (EG: 5V 1A RAVpower) Standard 5v
SD card used | (EG: SanDisk ultra) Pimroni-supplied 32GB Sandisk

Additional Information (if applicable)

Software title Radarr
Was the software title installed freshly or updated/migrated? Updated from Sep 25 2022 release to Jan 4 2023 release.
Can this issue be replicated on a fresh installation of DietPi? Unsure. I've had this install of dietpi for a while and have updated multiple times.

Steps to reproduce

Install radarr with sep 2022 release.
Update to jan 2023 release within webapp
Refresh

Expected behaviour

Update succeeds and radarr restarts without error

Actual behaviour

Service fails to start.

Extra details

journalctl -u radarr => https://pastebin.com/EzgKAVng

$ rm -rf /opt/radarr && dietpi-software reinstall 145 fixed the issue and kept my data, but still submitting as this will save others some googling in the future :)

MichaIng commented 1 year ago

Thanks for reporting.

Is your system 64-bit userland or did it switch to 64-bit kernel after the last bootloader upgrade?

dpkg --print-architecture

dasrocky commented 1 year ago

I faced the same issue on same device, luckily his last suggestion to reinstall solved it.

dpkg --print-architecture

Mine is arm64

MichaIng commented 1 year ago

@dasrocky Did you also see this

.NET location: Not found

error? Looks like an incomplete update to me.

bakerboy448 commented 1 year ago

You'd need the radarr updater log.

most likely something wiped your /tmp thus cause an incomplete update and the inability for the update to rollback

MichaIng commented 1 year ago

Did you both had the .NET variant installed before? Basically this is a good check, as long as you do not have Sonarr installed:

dpkg -l | grep mono

This is only installed on ARMv6 RPi models, but some time ago Radarr did require Mono on all architectures.

But yeah, I also tend to agree that something went wrong during the web update, it's just the question why.

bakerboy448 commented 1 year ago

Dotnet is not needed for the Radarr/Lidarr/Readarr/Prowlarr/SonarrV4; they're self contained

MichaIng commented 1 year ago

As .NET does not support ARMv6, for RPi 1 and Zero (1) models Mono it is still required. For everything else, that is the reason why we do not install it anymore. But it was required for older *arr versions, so depending on when users did install it, they may still have the Mono version. Of course the web UI updater is then expected to keep downloading the Mono version as long as its available, otherwise deny the update.

Sonarr V4 is not available yet, but I'm hoping for a soon release to get rid of Mono.

bakerboy448 commented 1 year ago

Sonarr v4 is in public beta

Radarr's last mono build was v3.2.2 which is end of life and not supported

MichaIng commented 1 year ago

Radarr's last mono build was v3.2.2 which is end of life and not supported

Still, the only way to get it running on ARMv6 devices. However, I think we're drifting off-topic. It is about a potential updater issue here and I want to find out whether the reason is that the updater was probably switching from Mono version to .NET version unintentionally. For this is it irrelevant why the Mono version was installed.

bakerboy448 commented 1 year ago

whether the reason is that the updater was probably switching from Mono version to .NET version unintentionally

this is not possible. The dotnet version is a separate install and mono cannot update to dotnet.

again, the most likely cause - and is commonly seen with DietPi - is /tmp being wiped while radarr is mid-update thus causing the upgrade to fail and also causing the rollback to fail. Updater logs would be required to even have any idea on the cause.

dasrocky commented 1 year ago

.NET location: Not found

i dont remember the error, now I cant check coz I reinstalled it. But I am sure the issue is same as OP.

bakerboy448 commented 1 year ago

Updater logs should still be available unless you or the DietPi install logic wiped them. https://wiki.servarr.com/radarr/troubleshooting#update-logs-location

MichaIng commented 1 year ago

this is not possible.

Are you related to Radarr to know this for such sure?

is /tmp being wiped while radarr is mid-update

There is no mechanism I'm aware of why /tmp would be wiped, neither on DietPi, nor on any other OS. This would break a lot more and much more regular than Radarr updates.

The point here is that shortly after latest Radarr release two users reported the same symptom which never appeared before. So it is obvious to assume that something changed in a way that updates from certain version to the latest fail.

Updater logs would be required to even have any idea on the cause.

Agreed, but you can see the journalctl -u radarr yourself above which does not contain the updater logs anymore, i.e. a reboot was done. @dasrocky a reinstall does not clear the system/service logs, so does this command show more in your case?

Something I can think of: Same as the service from the Wiki, we use:

TimeoutStopSec=20
KillMode=process
Restart=on-failure

So when the service is stopped, is is given 20 seconds before a SIGTERM is sent. I'm actually not sure whether this implies automatic restarts after the main process exits: https://www.freedesktop.org/software/systemd/man/systemd.service.html#TimeoutStopSec=
More importantly, SIGTERM is not sent to the whole control group, but only to the main process, so the updater is not killed when the main process exits (which it does when the updater starts).
The systemd unit then restarts the main process automatically, as the main process exiting in this case is seen as "failure".
What I am not sure about, if the updater now takes more than 20 seconds, is Radarr started up again while the updater is still running, and does not not only lead to a temporary startup loop but break the updater as well? That would be either a changed behaviour with latest Radarr or the update takes notably longer than it did before, so that this timeout needs to be increased.

I'll try to test this.

bakerboy448 commented 1 year ago

Are you related to Radarr to know this for such sure?

https://wiki.servarr.com/radarr/system#fixing-standalone-installs

So it is obvious to assume that something changed in a way that updates from certain version to the latest fail.

If it was obvious and due to a breaking update then there would be thousands of the hundreds of thousands of users complaining. Furthermore, this issue is seen time and time again after master releases and every single time the fix is a in-place reinstall & the cause was the update files being deleted or removed by the system or another app which the updater log confirms.

journal doesn't matter - only the log file does and the updated log file would hold the key to exactly what the issue is/was.

MichaIng commented 1 year ago

If it was obvious and due to a breaking update then there would be thousands of the hundreds of thousands of users complaining.

I do not mean that every update fails, but I mean that there are certain circumstances or certain older Radarr versions form which the updates may now fail, resp. the change has raised that an update in this circumstance fails.

Furthermore, this issue is seen time and time again after master releases

A reason to have a closer look, isn't it? Of course it is possible, but it is extremely unlikely that the system or another app (especially since most apps do not run as root, hopefully), just removes other apps' /tmp files. I've not seen the reports you refer to, but we are maintaining a lot of applications/implementations for a long time and I've never seen such once. So I'm at least suspicious and think it is worth to at least not rule out the reason to be elsewhere among Radarr itself or the systemd unit.

journal doesn't matter - only the log file does

Ah right, in ~/mnt/dietpi_userdata/radarr/logs/ resp. /var/log/radarr/ (symlinked) 👍. However, with RAM logging enabled they only last for 1 hour. But I do remember that the updater logs to STDOUT (hence journal) as well, or I mix it up.~ EDIT: Updater logs are separate and persistent in /mnt/dietpi_userdata/radarr/logs/UpdateLogs/.

MichaIng commented 1 year ago

If anyone is landing here, please provide journalctl -u radarr before doing a reboot + the content of the related log file in /mnt/dietpi_userdata/radarr/UpdateLogs/ (that one is not link to a tmpfs, hence also survives reboots). EDIT: Please take care to clean the journal output form any personal/sensitive/identifying information: https://github.com/MichaIng/DietPi/issues/6309#issuecomment-1518127781

@TDuffinNTU @dasrocky Could you check for and paste the updater log from this directory?

Did own tests now:

"Sep 25, 2022" was actually quite precise: https://github.com/Radarr/Radarr/releases/tag/v4.2.4.6635

Did some tests starting with this version and updating to latest. Always worked well here. The idea with the too short systemd unit timeout can be ruled out: The main process does not exist before the updater has finished. Below logs are with TimeoutStopSec=5, which looks identical to TimeoutStopSec=20, so it has no effect here. Service logs:

Apr 21 18:35:42 VM-Bullseye Radarr[1706]: [Info] InstallUpdateService: Deleting old update files
Apr 21 18:35:42 VM-Bullseye Radarr[1706]: [Info] InstallUpdateService: Downloading update 4.4.4.7068
Apr 21 18:35:56 VM-Bullseye Radarr[1706]: [Info] InstallUpdateService: Verifying update package
Apr 21 18:35:57 VM-Bullseye Radarr[1706]: [Info] InstallUpdateService: Update package verified successfully
Apr 21 18:35:57 VM-Bullseye Radarr[1706]: [Info] InstallUpdateService: Extracting Update package
Apr 21 18:36:01 VM-Bullseye Radarr[1706]: [Info] InstallUpdateService: Update package extracted successfully
Apr 21 18:36:01 VM-Bullseye Radarr[1706]: [Info] BackupService: Starting Backup
Apr 21 18:36:02 VM-Bullseye Radarr[1706]: [Info] InstallUpdateService: Preparing client
Apr 21 18:36:03 VM-Bullseye Radarr[1706]: [Info] InstallUpdateService: Starting update client /tmp/radarr_update/Radarr.Update
Apr 21 18:36:03 VM-Bullseye Radarr[1706]: [Info] InstallUpdateService: Radarr will restart shortly.
Apr 21 18:36:13 VM-Bullseye systemd[1]: radarr.service: Main process exited, code=killed, status=9/KILL
Apr 21 18:36:13 VM-Bullseye systemd[1]: radarr.service: Failed with result 'signal'.
Apr 21 18:36:13 VM-Bullseye systemd[1]: radarr.service: Unit process 1755 (Radarr.Update) remains running after unit stopped.
Apr 21 18:36:13 VM-Bullseye systemd[1]: radarr.service: Consumed 46.174s CPU time.
Apr 21 18:36:13 VM-Bullseye systemd[1]: radarr.service: Scheduled restart job, restart counter is at 1.
Apr 21 18:36:13 VM-Bullseye systemd[1]: Stopped Radarr (DietPi).
Apr 21 18:36:13 VM-Bullseye systemd[1]: radarr.service: Consumed 46.272s CPU time.
Apr 21 18:36:13 VM-Bullseye systemd[1]: radarr.service: Found left-over process 1755 (Radarr.Update) in control group while starting unit. Ignoring.
Apr 21 18:36:13 VM-Bullseye systemd[1]: This usually indicates unclean termination of a previous run, or service implementation deficiencies.
Apr 21 18:36:13 VM-Bullseye systemd[1]: Started Radarr (DietPi).
Apr 21 18:36:14 VM-Bullseye Radarr[1772]: [Info] Bootstrap: Starting Radarr - /opt/radarr/Radarr - Version 4.4.4.7068

Updater logs:

2023-04-21 18:36:13.2|Debug|DiskTransferService|Copy [/tmp/radarr_update/Radarr/Microsoft.AspNetCore.DataProtection.dll] > [/opt/radarr/Microsoft.AspNetCore.DataProtection.dll]
2023-04-21 18:36:13.2|Debug|DiskProvider|Setting permissions: 755 on /opt/radarr/Radarr
2023-04-21 18:36:13.2|Debug|DiskProvider|Setting permissions: 755 on /opt/radarr/ffprobe
2023-04-21 18:36:13.2|Info|TerminateNzbDrone|Killing all running processes
2023-04-21 18:36:13.2|Debug|ProcessProvider|Found 0 processes with the name: Radarr.Console
2023-04-21 18:36:13.2|Debug|ProcessProvider|Found 0 processes to kill
2023-04-21 18:36:13.3|Debug|ProcessProvider|Found 1 processes with the name: Radarr
2023-04-21 18:36:13.3|Debug|ProcessProvider| - [1706] Radarr
2023-04-21 18:36:13.3|Debug|ProcessProvider|Found 1 processes to kill
2023-04-21 18:36:13.3|Debug|ProcessProvider|Killing process: 1706 [Radarr]
2023-04-21 18:36:13.3|Info|ProcessProvider|[1706]: Killing process
2023-04-21 18:36:13.3|Info|ProcessProvider|[1706]: Waiting for exit
2023-04-21 18:36:13.3|Info|ProcessProvider|[1706]: Process terminated successfully
2023-04-21 18:36:13.3|Warn|ProcessProvider|Cannot find process with id: 1706
2023-04-21 18:36:13.3|Info|InstallUpdateService|Waiting for external auto-restart.
2023-04-21 18:36:14.4|Debug|ProcessProvider|Found 1 processes with the name: Radarr
2023-04-21 18:36:14.4|Debug|ProcessProvider| - [1772] Radarr
2023-04-21 18:36:14.4|Info|InstallUpdateService|Radarr was restarted by external process.
2023-04-21 18:36:14.4|Debug|ProcessProvider|Found 1 processes with the name: Radarr
2023-04-21 18:36:14.4|Debug|ProcessProvider| - [1772] Radarr
2023-04-21 18:36:14.4|Info|UpdateApp|Update completed successfully

So the updater process itself kills the main process after it has finished.

bakerboy448 commented 1 year ago

Note the journal / console is not cleansed and will contain uncensored api keys / crews etc. this is why logs - not journal or console output - are asked for

the journal output will likely not contain anything useful that the log file & updated log wouldn't already contain

MichaIng commented 1 year ago

Note the journal / console is not cleansed and will contain uncensored api keys / crews etc.

Ayyy, very good to know, thanks for the hint! The journal log however contains the systemd/service logs, i.e. when systemd detects the main process to have exited, the remaining child processes, what it does (sending signals or not) etc. So until we do not know the reason for the failure, I find those quite important to get the full picture. But should be carefully cleaned then.

MichaIng / DietPi