Scan Loop Fortification (#1573)

* Cleanup some messaging in the scan loop to be more context bearing

* Added Response Caching to Series Detail for 1 min, due to the heavy nature of the call.

* Refactored code to make it so that processing of series runs sync correctly.

Added a log to inform the user of corrupted volume from buggy code in v0.5.6.

* Moved folder watching out of experimental

* Fixed an issue where empty folders could break the scan loop

* Another fix for when dates aren't valid, the scanner wouldn't get the proper min and would throw an exception (develop)

* Implemented the ability to edit release year from the UI for a series.

* Added a unit test for some new logic

* Code smells

* Rewrote the handler for suspending watching to be more resilient and ensure no two threads have a race condition.

* More error handling for when a ScanFolder is invoked but multiple series belong to that folder, log it to the user and default to a library scan.

* ScanSeries now will check for kavitaignores higher than it's own folder and respect library level.

* Fixed an issue where image series with a folder name containing the word "folder" could get ignored as it thought the image was a cover image.

When a series folder is moved or deleted, skip parent ignore finding.

* Removed some old files, added in scanFolder a check if the series found for a folder is in a book library and if so to always do a library scan (as books are often nested into one folder with  multiple series). Added some unit tests

* Refactored some scan loop logic into ComicInfo, wrote tests and updated some documentation to make the fields more clear.

* Added a test for GetLastWriteTime based on recent bug

* Cleaned up some redundant code

* Fixed a bad merge

* Code smells

* Removed a package that's no longer used.

* Ensure we check against ScanQueue on ScanFolder enqueuing

* Documentation and more bullet proofing to ensure Hangfire checks work more as expected
This commit is contained in:
Joe Milazzo 2022-10-09 11:23:41 -05:00 committed by GitHub
parent 5a75a204db
commit 6ea9f2c73e
No known key found for this signature in database
GPG key ID: 4AEE18F83AFDEB23
20 changed files with 391 additions and 250 deletions

View file

@ -38,7 +38,7 @@ public class LibraryWatcher : ILibraryWatcher
private readonly IDirectoryService _directoryService;
private readonly IUnitOfWork _unitOfWork;
private readonly ILogger<LibraryWatcher> _logger;
private readonly IScannerService _scannerService;
private readonly ITaskScheduler _taskScheduler;
private static readonly Dictionary<string, IList<FileSystemWatcher>> WatcherDictionary = new ();
/// <summary>
@ -54,18 +54,19 @@ public class LibraryWatcher : ILibraryWatcher
/// <summary>
/// Counts within a time frame how many times the buffer became full. Is used to reschedule LibraryWatcher to start monitoring much later rather than instantly
/// </summary>
private int _bufferFullCounter = 0;
private int _bufferFullCounter;
/// <summary>
/// Used to lock buffer Full Counter
/// </summary>
private static readonly object Lock = new ();
private DateTime _lastBufferOverflow = DateTime.MinValue;
public LibraryWatcher(IDirectoryService directoryService, IUnitOfWork unitOfWork, ILogger<LibraryWatcher> logger, IScannerService scannerService, IHostEnvironment environment)
public LibraryWatcher(IDirectoryService directoryService, IUnitOfWork unitOfWork,
ILogger<LibraryWatcher> logger, IHostEnvironment environment, ITaskScheduler taskScheduler)
{
_directoryService = directoryService;
_unitOfWork = unitOfWork;
_logger = logger;
_scannerService = scannerService;
_taskScheduler = taskScheduler;
_queueWaitTime = environment.IsDevelopment() ? TimeSpan.FromSeconds(30) : TimeSpan.FromMinutes(5);
@ -91,8 +92,8 @@ public class LibraryWatcher : ILibraryWatcher
watcher.Created += OnCreated;
watcher.Deleted += OnDeleted;
watcher.Error += OnError;
watcher.Disposed += (sender, args) =>
_logger.LogError("[LibraryWatcher] watcher was disposed when it shouldn't have been");
watcher.Disposed += (_, _) =>
_logger.LogError("[LibraryWatcher] watcher was disposed when it shouldn't have been. Please report this to Kavita dev");
watcher.Filter = "*.*";
watcher.IncludeSubdirectories = true;
@ -127,16 +128,14 @@ public class LibraryWatcher : ILibraryWatcher
{
_logger.LogDebug("[LibraryWatcher] Restarting watcher");
UpdateBufferOverflow();
StopWatching();
await StartWatching();
}
private void OnChanged(object sender, FileSystemEventArgs e)
{
_logger.LogDebug("[LibraryWatcher] Changed: {FullPath}, {Name}, {ChangeType}", e.FullPath, e.Name, e.ChangeType);
if (e.ChangeType != WatcherChangeTypes.Changed) return;
_logger.LogDebug("[LibraryWatcher] Changed: {FullPath}, {Name}", e.FullPath, e.Name);
BackgroundJob.Enqueue(() => ProcessChange(e.FullPath, string.IsNullOrEmpty(_directoryService.FileSystem.Path.GetExtension(e.Name))));
}
@ -158,20 +157,31 @@ public class LibraryWatcher : ILibraryWatcher
BackgroundJob.Enqueue(() => ProcessChange(e.FullPath, true));
}
/// <summary>
/// On error, we count the number of errors that have occured. If the number of errors has been more than 2 in last 10 minutes, then we suspend listening for an hour
/// </summary>
/// <remarks>This will schedule jobs to decrement the buffer full counter</remarks>
/// <param name="sender"></param>
/// <param name="e"></param>
private void OnError(object sender, ErrorEventArgs e)
{
_logger.LogError(e.GetException(), "[LibraryWatcher] An error occured, likely too many changes occured at once or the folder being watched was deleted. Restarting Watchers");
_bufferFullCounter += 1;
_lastBufferOverflow = DateTime.Now;
bool condition;
lock (Lock)
{
_bufferFullCounter += 1;
condition = _bufferFullCounter >= 3;
}
if (_bufferFullCounter >= 3)
if (condition)
{
_logger.LogInformation("[LibraryWatcher] Internal buffer has been overflown multiple times in past 10 minutes. Suspending file watching for an hour");
StopWatching();
BackgroundJob.Schedule(() => RestartWatching(), TimeSpan.FromHours(1));
return;
}
Task.Run(RestartWatching);
BackgroundJob.Schedule(() => UpdateLastBufferOverflow(), TimeSpan.FromMinutes(10));
}
@ -185,8 +195,6 @@ public class LibraryWatcher : ILibraryWatcher
// ReSharper disable once MemberCanBePrivate.Global
public async Task ProcessChange(string filePath, bool isDirectoryChange = false)
{
UpdateBufferOverflow();
var sw = Stopwatch.StartNew();
_logger.LogDebug("[LibraryWatcher] Processing change of {FilePath}", filePath);
try
@ -214,29 +222,16 @@ public class LibraryWatcher : ILibraryWatcher
return;
}
// Check if this task has already enqueued or is being processed, before enqueing
var alreadyScheduled =
TaskScheduler.HasAlreadyEnqueuedTask(ScannerService.Name, "ScanFolder", new object[] {fullPath});
if (!alreadyScheduled)
{
_logger.LogInformation("[LibraryWatcher] Scheduling ScanFolder for {Folder}", fullPath);
BackgroundJob.Schedule(() => _scannerService.ScanFolder(fullPath), _queueWaitTime);
}
else
{
_logger.LogInformation("[LibraryWatcher] Skipped scheduling ScanFolder for {Folder} as a job already queued",
fullPath);
}
_taskScheduler.ScanFolder(fullPath, _queueWaitTime);
}
catch (Exception ex)
{
_logger.LogError(ex, "[LibraryWatcher] An error occured when processing a watch event");
}
_logger.LogDebug("[LibraryWatcher] ProcessChange ran in {ElapsedMilliseconds}ms", sw.ElapsedMilliseconds);
_logger.LogDebug("[LibraryWatcher] ProcessChange completed in {ElapsedMilliseconds}ms", sw.ElapsedMilliseconds);
}
private string GetFolder(string filePath, IList<string> libraryFolders)
private string GetFolder(string filePath, IEnumerable<string> libraryFolders)
{
var parentDirectory = _directoryService.GetParentDirectoryName(filePath);
_logger.LogDebug("[LibraryWatcher] Parent Directory: {ParentDirectory}", parentDirectory);
@ -256,14 +251,17 @@ public class LibraryWatcher : ILibraryWatcher
return Parser.Parser.NormalizePath(_directoryService.FileSystem.Path.Join(libraryFolder, rootFolder.First()));
}
private void UpdateBufferOverflow()
/// <summary>
/// This is called via Hangfire to decrement the counter. Must work around a lock
/// </summary>
// ReSharper disable once MemberCanBePrivate.Global
public void UpdateLastBufferOverflow()
{
if (_bufferFullCounter == 0) return;
// If the last buffer overflow is over 5 mins back, we can remove a buffer count
if (_lastBufferOverflow < DateTime.Now.Subtract(TimeSpan.FromMinutes(5)))
lock (Lock)
{
_bufferFullCounter = Math.Min(0, _bufferFullCounter - 1);
_lastBufferOverflow = DateTime.Now;
if (_bufferFullCounter == 0) return;
_bufferFullCounter -= 1;
}
}
}