danvics/rdt-client
1
0
Fork 0
Code Issues Pull requests Projects Releases Packages Wiki Activity Actions

Add logging and fixed issue with the torrentrunner hanging sometimes.

Browse source
This commit is contained in:
Roger Far 2021-02-12 14:39:20 -07:00
parent fda4727439
commit 290ed4c7de
13 changed files with 202 additions and 63 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

2
client/src/app/navbar/navbar.component.html
View file

@ -49,7 +49,7 @@
<a class="navbar-item"> Profile </a>
<a class="navbar-item" (click)="logout()"> Logout </a>
<hr class="navbar-divider" />
<div class="navbar-item">Version 1.5.4</div>
<div class="navbar-item">Version 1.5.5</div>
</div>
</div>
</div>

15
client/src/app/navbar/settings/settings.component.html
View file

@ -18,6 +18,21 @@
</p>
</div>
<div class="field">
<label class="label">Log level</label>
<div class="control select is-fullwidth">
<select [(ngModel)]="settingLogLevel">
<option value="Verbose">Verbose</option>
<option value="Debug">Debug</option>
<option value="Information">Information</option>
<option value="Warning">Warning</option>
<option value="Error">Error</option>
<option value="Fatal">Fatal</option>
</select>
</div>
<p class="help">Recommended level is Warning, set to Debug to get the most info.</p>
</div>
<div class="field">
<label class="label">Download path</label>
<div class="control">

6
client/src/app/navbar/settings/settings.component.ts
View file

@ -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,

6
server/RdtClient.Data/Data/DataContext.cs
View file

@ -123,6 +123,12 @@ namespace RdtClient.Data.Data
SettingId = "ProxyServer",
Type = "String",
Value = ""
},
new Setting
{
SettingId = "LogLevel",
Type = "String",
Value = "Warning"
}
};

8
server/RdtClient.Data/Models/Internal/AppSettings.cs
View file

@ -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; }

2
server/RdtClient.Service/Services/Settings.cs
View file

@ -29,7 +29,7 @@ namespace RdtClient.Service.Services
{
_settingData = settingData;
}
public async Task<IList<Setting>> GetAll()
{
return await _settingData.GetAll();

168
server/RdtClient.Service/Services/TorrentRunner.cs
View file

@ -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)");
}
}
}

11
server/RdtClient.Web/Controllers/SettingsController.cs
View file

@ -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<ActionResult> Update([FromBody] SettingsControllerUpdateRequest request)
{
await _settings.Update(request.Settings);
_torrents.Reset();
var logLevelSetting = await _settings.GetString("LogLevel");
if (!Enum.TryParse<LogEventLevel>(logLevelSetting, out var logLevel))
{
logLevel = LogEventLevel.Information;
}
Program.LoggingLevelSwitch.MinimumLevel = logLevel;
return Ok();
}

31
server/RdtClient.Web/Program.cs
View file

@ -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<DataContext>();
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<LogEventLevel>(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 =>

2
server/RdtClient.Web/RdtClient.Web.csproj
View file

@ -4,7 +4,7 @@
<TargetFramework>net5.0</TargetFramework>
<OutputType>Exe</OutputType>
<UserSecretsId>94c24cba-f03f-4453-a671-3640b517c573</UserSecretsId>
<Version>1.5.4</Version>
<Version>1.5.5</Version>
</PropertyGroup>
<ItemGroup>

2
server/RdtClient.Web/Startup.cs
View file

@ -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
{

6
server/RdtClient.Web/appsettings.Development.json
View file

@ -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",

6
server/RdtClient.Web/appsettings.json
View file

@ -1,11 +1,5 @@
{
"Logging": {
"LogLevel": {
"Default": "Information",
"Microsoft": "Warning",
"Microsoft.Hosting.Lifetime": "Warning",
"Hangfire": "Warning"
},
"File": {
"Path": "/data/db/rdtclient.log",
"Append": "True",