From 290ed4c7dec0c645765eaf37f20fde0ddc3e6453 Mon Sep 17 00:00:00 2001 From: Roger Far Date: Fri, 12 Feb 2021 14:39:20 -0700 Subject: [PATCH] Add logging and fixed issue with the torrentrunner hanging sometimes. --- client/src/app/navbar/navbar.component.html | 2 +- .../navbar/settings/settings.component.html | 15 ++ .../app/navbar/settings/settings.component.ts | 6 + server/RdtClient.Data/Data/DataContext.cs | 6 + .../Models/Internal/AppSettings.cs | 8 +- server/RdtClient.Service/Services/Settings.cs | 2 +- .../Services/TorrentRunner.cs | 168 ++++++++++++++---- .../Controllers/SettingsController.cs | 11 ++ server/RdtClient.Web/Program.cs | 31 +++- server/RdtClient.Web/RdtClient.Web.csproj | 2 +- server/RdtClient.Web/Startup.cs | 2 + .../appsettings.Development.json | 6 - server/RdtClient.Web/appsettings.json | 6 - 13 files changed, 202 insertions(+), 63 deletions(-) diff --git a/client/src/app/navbar/navbar.component.html b/client/src/app/navbar/navbar.component.html index bd10a95..0853ff0 100644 --- a/client/src/app/navbar/navbar.component.html +++ b/client/src/app/navbar/navbar.component.html @@ -49,7 +49,7 @@ Profile Logout
-
Version 1.5.4
+
Version 1.5.5
diff --git a/client/src/app/navbar/settings/settings.component.html b/client/src/app/navbar/settings/settings.component.html index 0bcc145..1175470 100644 --- a/client/src/app/navbar/settings/settings.component.html +++ b/client/src/app/navbar/settings/settings.component.html @@ -18,6 +18,21 @@

+
+ +
+ +
+

Recommended level is Warning, set to Debug to get the most info.

+
+
diff --git a/client/src/app/navbar/settings/settings.component.ts b/client/src/app/navbar/settings/settings.component.ts index cb8cb0e..1440e00 100644 --- a/client/src/app/navbar/settings/settings.component.ts +++ b/client/src/app/navbar/settings/settings.component.ts @@ -35,6 +35,7 @@ export class SettingsComponent implements OnInit { public testWriteSpeedError: string; public testWriteSpeedSuccess: number; + public settingLogLevel: string; public settingRealDebridApiKey: string; public settingDownloadPath: string; public settingMappedPath: string; @@ -59,6 +60,7 @@ export class SettingsComponent implements OnInit { this.settingsService.get().subscribe( (results) => { this.settingRealDebridApiKey = this.getSetting(results, 'RealDebridApiKey'); + this.settingLogLevel = this.getSetting(results, 'LogLevel'); this.settingDownloadPath = this.getSetting(results, 'DownloadPath'); this.settingMappedPath = this.getSetting(results, 'MappedPath'); this.settingTempPath = this.getSetting(results, 'TempPath'); @@ -86,6 +88,10 @@ export class SettingsComponent implements OnInit { settingId: 'RealDebridApiKey', value: this.settingRealDebridApiKey, }, + { + settingId: 'LogLevel', + value: this.settingLogLevel, + }, { settingId: 'DownloadPath', value: this.settingDownloadPath, diff --git a/server/RdtClient.Data/Data/DataContext.cs b/server/RdtClient.Data/Data/DataContext.cs index 46048fb..eada789 100644 --- a/server/RdtClient.Data/Data/DataContext.cs +++ b/server/RdtClient.Data/Data/DataContext.cs @@ -123,6 +123,12 @@ namespace RdtClient.Data.Data SettingId = "ProxyServer", Type = "String", Value = "" + }, + new Setting + { + SettingId = "LogLevel", + Type = "String", + Value = "Warning" } }; diff --git a/server/RdtClient.Data/Models/Internal/AppSettings.cs b/server/RdtClient.Data/Models/Internal/AppSettings.cs index eff5c07..6620a97 100644 --- a/server/RdtClient.Data/Models/Internal/AppSettings.cs +++ b/server/RdtClient.Data/Models/Internal/AppSettings.cs @@ -13,15 +13,9 @@ namespace RdtClient.Data.Models.Internal public class AppSettingsLogging { - public AppSettingsLoggingLogLevel LogLevel { get; set; } public AppSettingsLoggingFile File { get; set; } } - - public class AppSettingsLoggingLogLevel - { - public String Default { get; set; } - } - + public class AppSettingsLoggingFile { public String Path { get; set; } diff --git a/server/RdtClient.Service/Services/Settings.cs b/server/RdtClient.Service/Services/Settings.cs index e77e95a..347afb1 100644 --- a/server/RdtClient.Service/Services/Settings.cs +++ b/server/RdtClient.Service/Services/Settings.cs @@ -29,7 +29,7 @@ namespace RdtClient.Service.Services { _settingData = settingData; } - + public async Task> GetAll() { return await _settingData.GetAll(); diff --git a/server/RdtClient.Service/Services/TorrentRunner.cs b/server/RdtClient.Service/Services/TorrentRunner.cs index 4494d30..ce73044 100644 --- a/server/RdtClient.Service/Services/TorrentRunner.cs +++ b/server/RdtClient.Service/Services/TorrentRunner.cs @@ -1,11 +1,13 @@ using System; using System.Collections.Concurrent; +using System.Diagnostics; using System.IO; using System.Linq; using System.Threading.Tasks; using System.Web; using RdtClient.Data.Enums; using RdtClient.Service.Helpers; +using Serilog; namespace RdtClient.Service.Services { @@ -63,11 +65,17 @@ namespace RdtClient.Service.Services public async Task Tick() { + var sw = new Stopwatch(); + sw.Start(); + + Log.Debug("TorrentRunner Tick Start"); + var settings = await _settings.GetAll(); var settingApiKey = settings.GetString("RealDebridApiKey"); if (String.IsNullOrWhiteSpace(settingApiKey)) { + Log.Debug($"No RealDebridApiKey set!"); return; } @@ -100,55 +108,72 @@ namespace RdtClient.Service.Services return; } + Log.Debug($"Currently {ActiveDownloadClients.Count} active downloads"); + Log.Debug($"Currently {ActiveUnpackClients.Count} active unpacks"); + // Check if any torrents are finished downloading to the host, remove them from the active download list. var completedActiveDownloads = ActiveDownloadClients.Where(m => m.Value.Finished).ToList(); - if (completedActiveDownloads.Count > 0) + Log.Debug($"Processing {completedActiveDownloads.Count} completed downloads"); + + foreach (var (downloadId, downloadClient) in completedActiveDownloads) { - foreach (var (downloadId, downloadClient) in completedActiveDownloads) + if (downloadClient.Error != null) { - if (downloadClient.Error != null) - { - await _downloads.UpdateError(downloadId, downloadClient.Error); - await _downloads.UpdateCompleted(downloadId, DateTimeOffset.UtcNow); - } - else - { - await _downloads.UpdateDownloadFinished(downloadId, DateTimeOffset.UtcNow); - await _downloads.UpdateUnpackingQueued(downloadId, DateTimeOffset.UtcNow); - } + Log.Debug($"Processing active download {downloadId}: error {downloadClient.Error}"); - ActiveDownloadClients.TryRemove(downloadId, out _); + await _downloads.UpdateError(downloadId, downloadClient.Error); + await _downloads.UpdateCompleted(downloadId, DateTimeOffset.UtcNow); } - } + else + { + Log.Debug($"Processing active download {downloadId}: finished succesfully"); + await _downloads.UpdateDownloadFinished(downloadId, DateTimeOffset.UtcNow); + await _downloads.UpdateUnpackingQueued(downloadId, DateTimeOffset.UtcNow); + } + + ActiveDownloadClients.TryRemove(downloadId, out _); + + Log.Debug($"Removed active download {downloadId} from queue"); + } + // Check if any torrents are finished unpacking, remove them from the active unpack list. var completedUnpacks = ActiveUnpackClients.Where(m => m.Value.Finished).ToList(); + + Log.Debug($"Processing {completedUnpacks.Count} completed extractions"); - if (completedUnpacks.Count > 0) + foreach (var (downloadId, unpackClient) in completedUnpacks) { - foreach (var (downloadId, unpackClient) in completedUnpacks) + if (unpackClient.Error != null) { - if (unpackClient.Error != null) - { - await _downloads.UpdateError(downloadId, unpackClient.Error); - await _downloads.UpdateCompleted(downloadId, DateTimeOffset.UtcNow); - } - else - { - await _downloads.UpdateUnpackingFinished(downloadId, DateTimeOffset.UtcNow); - await _downloads.UpdateCompleted(downloadId, DateTimeOffset.UtcNow); - } + Log.Debug($"Processing active unpack {downloadId}: error {unpackClient.Error}"); - ActiveUnpackClients.TryRemove(downloadId, out _); + await _downloads.UpdateError(downloadId, unpackClient.Error); + await _downloads.UpdateCompleted(downloadId, DateTimeOffset.UtcNow); } + else + { + Log.Debug($"Processing active unpack {downloadId}: finished succesfully"); + + await _downloads.UpdateUnpackingFinished(downloadId, DateTimeOffset.UtcNow); + await _downloads.UpdateCompleted(downloadId, DateTimeOffset.UtcNow); + } + + ActiveUnpackClients.TryRemove(downloadId, out _); + + Log.Debug($"Removed active unpack {downloadId} from queue"); } var torrents = await _torrents.Get(); + Log.Debug($"Found {torrents.Count} torrents"); + // Only poll RealDebrid every second when a hub is connected, otherwise every 30 seconds if (_nextUpdate < DateTime.UtcNow && torrents.Count > 0) { + Log.Debug($"Updating torrent info from RealDebrid"); + var updateTime = 30; if (RdtHub.HasConnections) @@ -162,6 +187,8 @@ namespace RdtClient.Service.Services // Re-get torrents to account for updated info torrents = await _torrents.Get(); + + Log.Debug($"Finished updating torrent info from RealDebrid, next update in {updateTime} seconds"); } torrents = torrents.Where(m => m.Completed == null).ToList(); @@ -169,18 +196,27 @@ namespace RdtClient.Service.Services // Check if there are any downloads that are queued and can be started. var queuedDownloads = torrents.SelectMany(m => m.Downloads) .Where(m => m.Completed == null && m.DownloadQueued != null && m.DownloadStarted == null) - .OrderBy(m => m.DownloadQueued); + .OrderBy(m => m.DownloadQueued) + .ToList(); + + Log.Debug($"Found {queuedDownloads.Count} torrents queued for download"); foreach (var download in queuedDownloads) { + Log.Debug($"Starting download {download.DownloadId}"); + if (TorrentRunner.ActiveDownloadClients.Count >= settingDownloadLimit) { - return; + Log.Debug($"Not starting download {download.DownloadId} because there are already the max number of downloads active"); + + continue; } if (TorrentRunner.ActiveDownloadClients.ContainsKey(download.DownloadId)) { - return; + Log.Debug($"Not starting download {download.DownloadId} because this download is already active"); + + continue; } download.DownloadStarted = DateTime.UtcNow; @@ -193,32 +229,47 @@ namespace RdtClient.Service.Services downloadPath = Path.Combine(downloadPath, download.Torrent.Category); } + Log.Debug($"Setting download path for {download.DownloadId} to {downloadPath}"); + // Start the download process var downloadClient = new DownloadClient(download, downloadPath); if (TorrentRunner.ActiveDownloadClients.TryAdd(download.DownloadId, downloadClient)) { + Log.Debug($"Added download {download.DownloadId} to active downloads"); + await downloadClient.Start(settings); + + Log.Debug($"Download {download.DownloadId} started"); } } // Check if there are any unpacks that are queued and can be started. var queuedUnpacks = torrents.SelectMany(m => m.Downloads) .Where(m => m.Completed == null && m.UnpackingQueued != null && m.UnpackingStarted == null) - .OrderBy(m => m.DownloadQueued); + .OrderBy(m => m.DownloadQueued) + .ToList(); + + Log.Debug($"Found {queuedUnpacks.Count} torrents queued for unpacking"); foreach (var download in queuedUnpacks) { + Log.Debug($"Starting unpack {download.DownloadId}"); + // Check if the unpacking process is even needed var uri = new Uri(download.Link); var fileName = uri.Segments.Last(); fileName = HttpUtility.UrlDecode(fileName); + Log.Debug($"Found file name {fileName} for {download.DownloadId}"); + var extension = Path.GetExtension(fileName); if (extension != ".rar") { + Log.Debug($"No need to unpack {download.DownloadId}, setting it as unpacked"); + download.UnpackingStarted = DateTimeOffset.UtcNow; download.UnpackingFinished = DateTimeOffset.UtcNow; download.Completed = DateTimeOffset.UtcNow; @@ -233,12 +284,16 @@ namespace RdtClient.Service.Services // Check if we have reached the download limit, if so queue the download, but don't start it. if (TorrentRunner.ActiveUnpackClients.Count >= settingUnpackLimit) { - return; + Log.Debug($"Not starting unpack {download.DownloadId} because there are already the max number of unpacks active"); + + continue; } if (TorrentRunner.ActiveUnpackClients.ContainsKey(download.DownloadId)) { - return; + Log.Debug($"Not starting unpack {download.DownloadId} because this download is already active"); + + continue; } download.UnpackingStarted = DateTimeOffset.UtcNow; @@ -251,12 +306,18 @@ namespace RdtClient.Service.Services downloadPath = Path.Combine(downloadPath, download.Torrent.Category); } + Log.Debug($"Setting unpack path for {download.DownloadId} to {downloadPath}"); + // Start the unpacking process var unpackClient = new UnpackClient(download, downloadPath); if (TorrentRunner.ActiveUnpackClients.TryAdd(download.DownloadId, unpackClient)) { + Log.Debug($"Added unpack {download.DownloadId} to active unpacks"); + await unpackClient.Start(); + + Log.Debug($"Unpack {download.DownloadId} started"); } } @@ -265,51 +326,74 @@ namespace RdtClient.Service.Services // If torrent is erroring out on the RealDebrid side, skip processing this torrent. if (torrent.RdStatus == RealDebridStatus.Error) { + Log.Debug($"Torrent {torrent.RdId} has an error: {torrent.RdStatusRaw}, not processing further"); + continue; } // RealDebrid is waiting for file selection, select which files to download. if (torrent.AutoDownload && torrent.RdStatus == RealDebridStatus.WaitingForFileSelection) { + Log.Debug($"Torrent {torrent.RdId} selecting files"); + var files = torrent.Files; if (settingOnlyDownloadAvailableFiles) { + Log.Debug($"Torrent {torrent.RdId} determining which files are already available"); + var availableFiles = await _torrents.GetAvailableFiles(torrent.Hash); + Log.Debug($"Found {availableFiles.Count} available files for torrent {torrent.RdId}"); + if (availableFiles.Count > 0) { files = torrent.Files.Where(m => availableFiles.Any(f => m.Path.EndsWith(f))).ToList(); + + Log.Debug($"Selecting {files.Count} available files for torrent {torrent.RdId}"); } } if (settingMinFileSize > 0) { + Log.Debug($"Torrent {torrent.RdId} determining which files are over {settingMinFileSize} bytes"); + files = files.Where(m => m.Bytes > settingMinFileSize).ToList(); + + Log.Debug($"Found {files.Count} files that match the minimum file size criterea for torrent {torrent.RdId}"); } if (files.Count == 0) { + Log.Debug($"Filtered all files out for {torrent.RdId}! Downloading ALL files!"); + files = torrent.Files; } var fileIds = files.Select(m => m.Id.ToString()).ToArray(); + Log.Debug($"Selecting files for torrent {torrent.RdId}: {String.Join(", ", fileIds)}"); + await _torrents.SelectFiles(torrent.RdId, fileIds); } // If the torrent doesn't have any files at this point, don't process it further. if (torrent.Files.Count == 0) { + Log.Debug($"No files found for torrent {torrent.RdId}!"); continue; } // RealDebrid finished downloading the torrent, process the file to host. if (torrent.AutoDownload && torrent.RdStatus == RealDebridStatus.Finished) { + Log.Debug($"Torrent {torrent.RdId} completed, download starting"); + // If the torrent doesn't have any Downloads, unrestrict the links and add them to the database. if (torrent.Downloads.Count == 0) { + Log.Debug($"Torrent {torrent.RdId} unrestricting links"); + await _torrents.Unrestrict(torrent.TorrentId); continue; @@ -322,10 +406,14 @@ namespace RdtClient.Service.Services m.DownloadFinished == null) .ToList(); + Log.Debug($"Torrent {torrent.RdId} found {downloadsPending.Count} downloads pending"); + if (downloadsPending.Count > 0) { foreach (var download in downloadsPending) { + Log.Debug($"Torrent {torrent.RdId} starting download {download.DownloadId}"); + await _torrents.Download(download.DownloadId); } @@ -335,6 +423,8 @@ namespace RdtClient.Service.Services if (torrent.AutoUnpack && torrent.RdStatus == RealDebridStatus.Finished) { + Log.Debug($"Torrent {torrent.RdId} completed, unpack starting"); + // If all files are finished downloading, move to the unpacking step. var unpackingPending = torrent.Downloads .Where(m => m.Completed == null && @@ -343,10 +433,14 @@ namespace RdtClient.Service.Services m.UnpackingFinished == null) .ToList(); + Log.Debug($"Torrent {torrent.RdId} found {unpackingPending.Count} unpacks pending"); + if (unpackingPending.Count > 0) { foreach (var download in unpackingPending) { + Log.Debug($"Torrent {torrent.RdId} starting unpack {download.DownloadId}"); + await _torrents.Unpack(download.DownloadId); } @@ -361,11 +455,15 @@ namespace RdtClient.Service.Services if (allComplete) { + Log.Debug($"Torrent {torrent.RdId} all downloads complete"); + await _torrents.UpdateComplete(torrent.TorrentId, DateTimeOffset.UtcNow); // Remove the torrent from RealDebrid if (torrent.AutoDelete) { + Log.Debug($"Torrent {torrent.RdId} removing"); + await _torrents.Delete(torrent.TorrentId, true, true, false); } } @@ -373,6 +471,10 @@ namespace RdtClient.Service.Services } await _remoteService.Update(); + + sw.Stop(); + + Log.Debug($"TorrentRunner Tick End (took {sw.ElapsedMilliseconds}ms)"); } } } diff --git a/server/RdtClient.Web/Controllers/SettingsController.cs b/server/RdtClient.Web/Controllers/SettingsController.cs index b4ae12e..a84a7bf 100644 --- a/server/RdtClient.Web/Controllers/SettingsController.cs +++ b/server/RdtClient.Web/Controllers/SettingsController.cs @@ -7,6 +7,7 @@ using Microsoft.AspNetCore.Mvc; using RdtClient.Data.Models.Data; using RdtClient.Service.Models; using RdtClient.Service.Services; +using Serilog.Events; namespace RdtClient.Web.Controllers { @@ -36,8 +37,18 @@ namespace RdtClient.Web.Controllers public async Task Update([FromBody] SettingsControllerUpdateRequest request) { await _settings.Update(request.Settings); + _torrents.Reset(); + var logLevelSetting = await _settings.GetString("LogLevel"); + + if (!Enum.TryParse(logLevelSetting, out var logLevel)) + { + logLevel = LogEventLevel.Information; + } + + Program.LoggingLevelSwitch.MinimumLevel = logLevel; + return Ok(); } diff --git a/server/RdtClient.Web/Program.cs b/server/RdtClient.Web/Program.cs index 284b9f4..b6d1a38 100644 --- a/server/RdtClient.Web/Program.cs +++ b/server/RdtClient.Web/Program.cs @@ -10,6 +10,7 @@ using RdtClient.Data.Data; using RdtClient.Data.Models.Internal; using RdtClient.Service.Services; using Serilog; +using Serilog.Core; using Serilog.Events; using Serilog.Exceptions; @@ -17,6 +18,8 @@ namespace RdtClient.Web { public class Program { + public static LoggingLevelSwitch LoggingLevelSwitch; + public static async Task Main(String[] args) { try @@ -29,6 +32,22 @@ namespace RdtClient.Web var dbContext = scope.ServiceProvider.GetRequiredService(); await dbContext.Database.MigrateAsync(); await dbContext.Seed(); + + var logLevelSettingDb = await dbContext.Settings.FirstOrDefaultAsync(m => m.SettingId == "LogLevel"); + + var logLevelSetting = "Warning"; + + if (logLevelSettingDb != null) + { + logLevelSetting = logLevelSettingDb.Value; + } + + if (!Enum.TryParse(logLevelSetting, out var logLevel)) + { + logLevel = LogEventLevel.Warning; + } + + LoggingLevelSwitch.MinimumLevel = logLevel; } await host.RunAsync(); @@ -61,19 +80,15 @@ namespace RdtClient.Web { appSettings.HostUrl = "http://0.0.0.0:6500"; } - - if (!Enum.TryParse(appSettings.Logging.LogLevel.Default, out LogEventLevel logLevel)) - { - logLevel = LogEventLevel.Information; - } + + LoggingLevelSwitch = new LoggingLevelSwitch(LogEventLevel.Debug); Log.Logger = new LoggerConfiguration() .Enrich.FromLogContext() .Enrich.WithExceptionDetails() - .WriteTo.File(appSettings.Logging.File.Path, logLevel, rollOnFileSizeLimit: true, fileSizeLimitBytes: appSettings.Logging.File.FileSizeLimitBytes, retainedFileCountLimit: appSettings.Logging.File.MaxRollingFiles) + .WriteTo.File(appSettings.Logging.File.Path, rollOnFileSizeLimit: true, fileSizeLimitBytes: appSettings.Logging.File.FileSizeLimitBytes, retainedFileCountLimit: appSettings.Logging.File.MaxRollingFiles) .WriteTo.Console() - .MinimumLevel.Override("Microsoft.EntityFrameworkCore.Database.Command", LogEventLevel.Warning) - .MinimumLevel.Information() + .MinimumLevel.ControlledBy(LoggingLevelSwitch) .CreateLogger(); Serilog.Debugging.SelfLog.Enable(msg => diff --git a/server/RdtClient.Web/RdtClient.Web.csproj b/server/RdtClient.Web/RdtClient.Web.csproj index 9fa74bb..109f74c 100644 --- a/server/RdtClient.Web/RdtClient.Web.csproj +++ b/server/RdtClient.Web/RdtClient.Web.csproj @@ -4,7 +4,7 @@ net5.0 Exe 94c24cba-f03f-4453-a671-3640b517c573 - 1.5.4 + 1.5.5 diff --git a/server/RdtClient.Web/Startup.cs b/server/RdtClient.Web/Startup.cs index f02e8e9..6c8dcba 100644 --- a/server/RdtClient.Web/Startup.cs +++ b/server/RdtClient.Web/Startup.cs @@ -1,3 +1,4 @@ +using System; using System.Threading.Tasks; using Microsoft.AspNetCore.Authentication.Cookies; using Microsoft.AspNetCore.Builder; @@ -13,6 +14,7 @@ using RdtClient.Data.Data; using RdtClient.Data.Models.Internal; using RdtClient.Service.Middleware; using RdtClient.Service.Services; +using Serilog.Events; namespace RdtClient.Web { diff --git a/server/RdtClient.Web/appsettings.Development.json b/server/RdtClient.Web/appsettings.Development.json index baa5fc3..38b9b8c 100644 --- a/server/RdtClient.Web/appsettings.Development.json +++ b/server/RdtClient.Web/appsettings.Development.json @@ -1,11 +1,5 @@ { "Logging": { - "LogLevel": { - "Default": "Debug", - "Microsoft": "Warning", - "Microsoft.Hosting.Lifetime": "Information", - "Hangfire": "Information" - }, "File": { "Path": "C:/Temp/rdtclient/rdtclient.log", "Append": "True", diff --git a/server/RdtClient.Web/appsettings.json b/server/RdtClient.Web/appsettings.json index f3f67de..e06bee2 100644 --- a/server/RdtClient.Web/appsettings.json +++ b/server/RdtClient.Web/appsettings.json @@ -1,11 +1,5 @@ { "Logging": { - "LogLevel": { - "Default": "Information", - "Microsoft": "Warning", - "Microsoft.Hosting.Lifetime": "Warning", - "Hangfire": "Warning" - }, "File": { "Path": "/data/db/rdtclient.log", "Append": "True",