Jackett can't start after auto-update (Windows)

[AnthonyBe]

Environment

OS: Windows 10 Pro x64 20H2 (19042.572)

.Net Runtime: .Net-Core 64-bit 2.1.516 / .Net-Framework 4.8 Windows 10 May 2020 Update (CLR 4.0)

.Net Version: 4.8 Windows 10 May 2020

Jackett Version: v0.16.1933

Last Working Jackett Version: v0.16.1933

Are you using a proxy or VPN? yes (AdGuard VPN)

Description

After never having an issue with auto-update of Jackett (beta versions), twice in the last week I've found Jackett in a broken state after attempting an auto-update. In this state, the Jackett service cannot be started manually.

The first time this occurred, I downloaded the current versions (v0.16.1922) and performed a manual install. Everything was fine at that point.
The most recent event was Jackett auto-updating from v0.16.1922 to v0.16.1933

After a manual install of the currently available beta release, and PC reboot, Jackett auto-starts and works fine.

Logged Error Messages

The Log.txt shows Jackett detecting the update, downloading it and preparing for update:

2020-10-29 23:21:52.5041 Info Checking for updates... Jackett variant: CoreWindows 
2020-10-29 23:21:53.1715 Info New release found. Current version: v0.16.1922 New version: v0.16.1933 
2020-10-29 23:21:53.1776 Info Downloading release v0.16.1933 It could take a while... 
2020-10-29 23:22:32.1824 Info Starting updater: C:\WINDOWS\TEMP\JackettUpdate-v0.16.1933-637396105410329030\Jackett\JackettUpdater.exe --Path "C:\ProgramData\Jackett" --Type "WindowsService" --Args " " --KillPids "26268" 
2020-10-29 23:22:32.2250 Info Updater started process id: 23692 
2020-10-29 23:22:32.2250 Info Signal sent to lock service 
2020-10-29 23:22:34.2465 Info Exiting Jackett.. 

The updater.txt shows a number of file lock errors during the update. This is a sample:

2020-10-29 23:28:49.1963 Error System.IO.IOException: The process cannot access the file 'C:\ProgramData\Jackett\System.Xml.ReaderWriter.dll' because it is being used by another process.
   at System.IO.FileSystem.CopyFile(String sourceFullPath, String destFullPath, Boolean overwrite)
   at System.IO.File.Copy(String sourceFileName, String destFileName, Boolean overwrite)
   at Jackett.Updater.Program.CopyUpdateFile(String jackettDestinationDirectory, String fullSourceFilePath, String updateSourceDirectory, Boolean previousAttemptFailed) in D:\a\1\s\src\Jackett.Updater\Program.cs:line 609 System.IO.IOException: The process cannot access the file 'C:\ProgramData\Jackett\System.Xml.ReaderWriter.dll' because it is being used by another process.
   at System.IO.FileSystem.CopyFile(String sourceFullPath, String destFullPath, Boolean overwrite)
   at System.IO.File.Copy(String sourceFileName, String destFileName, Boolean overwrite)
   at Jackett.Updater.Program.CopyUpdateFile(String jackettDestinationDirectory, String fullSourceFilePath, String updateSourceDirectory, Boolean previousAttemptFailed) in D:\a\1\s\src\Jackett.Updater\Program.cs:line 609

..and ultimately ends with:

2020-10-29 23:28:57.0587 Info Starting Windows service 
2020-10-29 23:28:58.1899 Info Failed to start service. Attempting to start console. 

The Windows Application log contains this matching error at 23:28:57:

Event ID: 1026
Application: JackettService.exe
CoreCLR Version: 4.700.20.47201
.NET Core Version: 3.1.9
Description: The process was terminated due to an unhandled exception.
Exception Info: System.IO.FileLoadException: Could not load file or assembly 'Jackett.Common, Version=0.16.1933.0, Culture=neutral, PublicKeyToken=null'. The located assembly's manifest definition does not match the assembly reference. (0x80131040)
File name: 'Jackett.Common, Version=0.16.1933.0, Culture=neutral, PublicKeyToken=null'
   at Jackett.Service.Service..ctor()
   at Jackett.Service.Program.Main() in D:\a\1\s\src\Jackett.Service\Program.cs:line 13

closely followed by

Faulting application name: JackettService.exe, version: 0.16.1933.0, time stamp: 0x5f6b3846
Faulting module name: KERNELBASE.dll, version: 10.0.19041.572, time stamp: 0x979ddb1d
Exception code: 0xe0434352
Fault offset: 0x00129ab2
Faulting process ID: 0x6fb0
Faulting application start time: 0x01d6adef1271e553
Faulting application path: C:\ProgramData\Jackett\JackettService.exe
Faulting module path: C:\WINDOWS\System32\KERNELBASE.dll
Report ID: aa212947-6ddb-496d-b6e3-40e31975034b
Faulting package full name: 
Faulting package-relative application ID: 

A manual install of v0.16.1999 completed successfully, but the service did not start. When I attempted to start it manually I found it in a Disabled state. When I attempted to change the state back to Automatic I got a "The specified service has been marked for deletion" error.

It was only after I rebooted, that Jackett then automatically started and was working fine.

updater.txt
TrayLog.txt
ServiceLog.txt
log.txt
net fw versions.txt

[garfield69]

Have seen several tickets recently about the Windows updater not succeeding.
And while I use Jackett daily on my win 10 and regularly click on the dashboard check for updates button after I publish a Jackett release, I have yet to have an instance of my Jackett failing to update, so I cannot seem to replicate this problem.
Ping to any volunteers familiar with windows and C# to investigate.

[AnthonyBe]

I've also seen no issue when I've manually triggered an update via the 'Check for updates' button. Seem to be restricted to the auto-update process.

[garfield69]

Ahh, ok, then I'll let the next few updates run on auto for a bit and see what happens.

[garfield69]

OK, the logs you provided were useful.
Timeline:
updater 2020-10-29 23:22:32.5892 Info Jackett Updater v0.16.1933 begins running
updater 2020-10-29 23:22:32.6085 Info Starting 30 second delay tray launch
sys-tray 2020-10-29 23:22:32.8421 Info Close of tray application initiated
sys-tray 2020-10-29 23:23:03.3317 Info Starting Jackett Tray v0.16.1922.0
updater 2020-10-29 23:24:46.2267 Error System.IO.IOException
boom

The reason I don't get this problem is because my system disc is SSD and I have a fairly high spec PC, so my updater run takes less that 10 seconds to complete.

It seems that for the Windows platform Jackett is relying on a 30 second timer delay to restart the sys-tray after it is shutdown, while the updater is running, and clearly for some users this is not long enough.

Obviously the ideal solution is for the sys-tray to be started after the update is completed rather than via a timer, but there obviously is no easy way to provide this, otherwise I assume it would have been done that way already.

A simple temporary solve would be to increase the timer delay.

Normally each successful copy on your computer takes about a millisecond to complete, and therefore 943 files should take no more that 95 seconds to complete.

I suppose then that a 2 minutes delay would be a place to start. @ilike2burnthing @ngosang any thoughts on this?

[ilike2burnthing]

I had to write a simple bat script a few years back to automate a fix for a game on each start, and then revert the fix after it was closed. Adapted for Jackett it would look something like:

@echo off
start JackettUpdater.exe
timeout /t 30 > NUL # if we wanted to keep the 30s delay
:_loop
tasklist /FI "IMAGENAME eq JackettUpdater.exe" | findstr = > NUL || goto _cleanup
timeout /t 5 > NUL
goto _loop
:_cleanup
C:\ProgramData\Jackett\JackettTray.exe

Something to work off at least, if for some reason the updater can't be changed to launch the tray once it's finished.

If that's not viable either, or we want a fix in the interim, then 2mins sounds plenty reasonable.

[ngosang]

I suppose then that a 2 minutes delay would be a place to start. @ilike2burnthing @ngosang any thoughts on this?

The right thing to do is to have an external process/script that waits until the updater ends. This solution is more reliable and doesn't waste user time in fast systems. Since I don't develop for Windows this solution is ok as a workaround. Please, open another issue as enhacement to improve this.

[garfield69]

@AnthonyBe so manually upgrade to Jackett 0.16.2040 and hopefully the next auto-update after that should start completing for you.

[AnthonyBe]

Hi @garfield69 - unfortunately, the delay increase has not resolved the issue for me.

I manually installed 0.16.2040 but auto-update since then has continued to fail with the same errors as before.

updater.txt
log.txt
ServiceLog.txt
TrayLog.txt

[garfield69]

updater 2020-11-06 18:55:09.8159 Info Jackett Updater v0.16.2080 
systray 2020-11-06 18:55:10.3529 Info Starting 120 second delay tray launch
systray 2020-11-06 18:57:11.8045 Info Starting Jackett Tray v0.16.2040.0 
updater 2020-11-06 18:59:01.5526 Error System.IO.IOException: 

basically your system is really slow :-(
I'm not going to bump the delay further, and I'm not going to implement a config option where you can set the delay time.
we are going to wait until #10094 is complete and this should solve the issue.

[garfield69]

Jackett 0.16.2096

[AnthonyBe]

Thanks @garfield69 - I've manually updated to 0.16.2096 so we'll see what happens in the next 24-48 hours when the next update is released!

BTW, the system I'm using is far from slow and the HDD being written to (%programdata%\Jackett) is an SSD. That said, I'm often running CPU intensive tasks which can impact application performance. I'm curious why this problem only started occurring from v0.16.1922 (or possibly the version before)?

[garfield69]

I'm curious why this problem only started occurring from v0.16.1922 (or possibly the version before)?

I suspect the potential for the issue has always been there.
Have you recently changed your workload habit on the machine, and begun dong very heavy work starting the last 15 days or so ago?
The sysTray code has not been changed for 8 months, and the Updater has only had logger messages updated a month ago.
So It's unlikely to be the results of Jackett code changes.

[ngosang]

@AnthonyBe any feedback?

[AnthonyBe]

@ngosang - Successful auto-update overnight from 0.16.2096 to 0.16.2124 :)

Thanks guys!

[garfield69]

Good work @ngosang and @ilike2burnthing .
Thank you.