diff --git a/listenarr.infrastructure/DownloadClients/Qbittorrent/QbittorrentItemFetchWorkflow.cs b/listenarr.infrastructure/DownloadClients/Qbittorrent/QbittorrentItemFetchWorkflow.cs index 45a624f1d..f1a599dac 100644 --- a/listenarr.infrastructure/DownloadClients/Qbittorrent/QbittorrentItemFetchWorkflow.cs +++ b/listenarr.infrastructure/DownloadClients/Qbittorrent/QbittorrentItemFetchWorkflow.cs @@ -87,14 +87,33 @@ public async Task> GetItemsAsync(DownloadClientConfigur foreach (var torrent in torrents) { - items.Add(QbittorrentResponseMapper.MapDownloadClientItem( - torrent, - client, - removeCompletedDownloads, - globalMaxRatioEnabled, - globalMaxRatio, - globalMaxSeedingTimeEnabled, - globalMaxSeedingTime)); + // Same per-item isolation as the queue fetch. This list is what completion and + // import decisions are made from, so a torrent lost here is not just a missing + // row in a view: everything after it stops being considered for import at all. + try + { + items.Add(QbittorrentResponseMapper.MapDownloadClientItem( + torrent, + client, + removeCompletedDownloads, + globalMaxRatioEnabled, + globalMaxRatio, + globalMaxSeedingTimeEnabled, + globalMaxSeedingTime)); + } + catch (Exception ex) when (ex is not OperationCanceledException && ex is not OutOfMemoryException && ex is not StackOverflowException) + { + var hash = torrent.TryGetValue("hash", out var hashEl) && hashEl.ValueKind == JsonValueKind.String + ? hashEl.GetString() ?? string.Empty + : string.Empty; + // Debug for the same reason as the queue fetch: the condition recurs on + // every poll and there is no operator action it calls for. + logger.LogDebug( + ex, + "Skipping unreadable qBittorrent torrent {TorrentHash} for client {ClientId}; the rest of the item list is unaffected", + LogRedaction.SanitizeText(hash), + LogRedaction.SanitizeText(client.Id)); + } } } catch (Exception ex) when (ex is not OperationCanceledException && ex is not OutOfMemoryException && ex is not StackOverflowException) diff --git a/listenarr.infrastructure/DownloadClients/Qbittorrent/QbittorrentQueueFetchWorkflow.cs b/listenarr.infrastructure/DownloadClients/Qbittorrent/QbittorrentQueueFetchWorkflow.cs index bd3c62a0a..ed1540f56 100644 --- a/listenarr.infrastructure/DownloadClients/Qbittorrent/QbittorrentQueueFetchWorkflow.cs +++ b/listenarr.infrastructure/DownloadClients/Qbittorrent/QbittorrentQueueFetchWorkflow.cs @@ -98,17 +98,48 @@ public async Task> GetQueueAsync(DownloadClientConfiguration cli foreach (var torrent in torrents) { - var hash = torrent.TryGetValue("hash", out var hashEl) ? hashEl.GetString() ?? string.Empty : string.Empty; + var hash = torrent.TryGetValue("hash", out var hashEl) && hashEl.ValueKind == JsonValueKind.String + ? hashEl.GetString() ?? string.Empty + : string.Empty; - List> files = []; - using var filesResp = await httpClient.GetAsync($"{baseUrl}/api/v2/torrents/files?hash={hash}", ct); - if (filesResp.IsSuccessStatusCode) + // One torrent that cannot be read must not take the rest of the response with + // it. Without this, an exception raised while mapping torrent N escapes the + // loop and is caught only by the handler below, so torrents N..end are dropped + // while the poll still reports itself as a healthy live snapshot: the queue + // simply appears shorter, with nothing to say a row was lost. + // + // HttpRequestException is excluded on purpose. The per-torrent files request + // sits inside this block, and a transport failure there means the client went + // away mid-poll, not that this torrent is unreadable. Swallowing it would log + // one warning per remaining torrent and hand the caller a short queue that + // still claims to be a healthy live snapshot, which is the failure this guard + // exists to stop. An error status from that request is already handled by the + // IsSuccessStatusCode check and does not reach here. + try { - var filesJson = await filesResp.Content.ReadAsStringAsync(ct); - files = JsonSerializer.Deserialize>>(filesJson) ?? []; - } + List> files = []; + using var filesResp = await httpClient.GetAsync($"{baseUrl}/api/v2/torrents/files?hash={Uri.EscapeDataString(hash)}", ct); + if (filesResp.IsSuccessStatusCode) + { + var filesJson = await filesResp.Content.ReadAsStringAsync(ct); + files = JsonSerializer.Deserialize>>(filesJson) ?? []; + } - items.Add(QbittorrentResponseMapper.MapQueueItem(torrent, client, files)); + items.Add(QbittorrentResponseMapper.MapQueueItem(torrent, client, files)); + } + catch (Exception ex) when (ex is not OperationCanceledException && ex is not HttpRequestException && ex is not OutOfMemoryException && ex is not StackOverflowException) + { + // Debug rather than Warning. A torrent whose fields the mapper cannot read + // does not heal, so this fires once per torrent on every poll for as long + // as the torrent sits in the client, and the operator has nothing to act + // on. TransmissionQueueFetchWorkflow logs the same condition at Debug for + // the same reason. The torrent's absence from the queue stays observable. + logger.LogDebug( + ex, + "Skipping unreadable qBittorrent torrent {TorrentHash} for client {ClientId}; the rest of the queue is unaffected", + LogRedaction.SanitizeText(hash), + LogRedaction.SanitizeText(client.Id)); + } } } catch (DownloadClientAdapterPollingException) diff --git a/tests/Features/Infrastructure/DownloadClients/Qbittorrent/QbittorrentAdapterTests.cs b/tests/Features/Infrastructure/DownloadClients/Qbittorrent/QbittorrentAdapterTests.cs index 038abe508..3499bc99c 100644 --- a/tests/Features/Infrastructure/DownloadClients/Qbittorrent/QbittorrentAdapterTests.cs +++ b/tests/Features/Infrastructure/DownloadClients/Qbittorrent/QbittorrentAdapterTests.cs @@ -495,6 +495,228 @@ public async Task GetQueueAsync_WithoutIds_ReturnsEmpty_OnQueueRequestFailure() Assert.Empty(items); } + // A queue response whose middle torrent carries `downloaded` in the given JSON token form. + // The torrents either side of it are well formed, so anything missing from the result is + // attributable to that one field. + private static string QueueWithMalformedMiddleTorrent(string malformedDownloaded) => $$""" + [ + { + "hash": "aaaa1111", "name": "First", "progress": 0.5, "size": 1000, + "downloaded": 500, "state": "downloading", "save_path": "/downloads/a" + }, + { + "hash": "bbbb2222", "name": "Second", "progress": 0.5, "size": 1000, + "downloaded": {{malformedDownloaded}}, "state": "downloading", "save_path": "/downloads/b" + }, + { + "hash": "cccc3333", "name": "Third", "progress": 0.5, "size": 1000, + "downloaded": 700, "state": "downloading", "save_path": "/downloads/c" + } + ] + """; + + // qBittorrent documents `downloaded` as an integer, so the typed accessor reading it is + // right about the normal case. It was not resilient about the abnormal one: a value in + // another token form threw out of the mapper, out of the loop walking the response, and + // took every torrent after it along with it, while the poll still reported itself as a + // healthy live snapshot. + // + // "600.5" is a JSON number that is not an integer (FormatException from GetInt64) and + // "\"600\"" is a quoted one (InvalidOperationException). The quoted form is the shape + // already reported against the NZBGet adapter in #618 and #619. + [Theory] + [InlineData("600.5")] + [InlineData("\"600\"")] + [InlineData("6e2")] + public async Task GetQueueAsync_WhenOneTorrentIsUnreadable_DropsOnlyThatTorrent(string malformedDownloaded) + { + var apiMock = _provider.GetRequiredService(); + apiMock.InfoResponseOverride = QueueWithMalformedMiddleTorrent(malformedDownloaded); + var gateway = (DownloadClientGateway)_provider.GetRequiredService(); + var adapter = (QbittorrentAdapter)gateway.ResolveAdapter(_client); + + var items = await adapter.GetQueueAsync(_client); + + // The torrent AFTER the unreadable one is the whole point. Asserting only that the + // list is non-empty would pass on the truncating behaviour, because the first torrent + // is mapped before anything throws. + Assert.Contains(items, item => item.Id == "aaaa1111"); + Assert.Contains(items, item => item.Id == "cccc3333"); + Assert.DoesNotContain(items, item => item.Id == "bbbb2222"); + Assert.Equal(2, items.Count); + } + + // The item list is the half of the guard that matters most: completion and import + // decisions are made from it, so a torrent lost here stops being considered for import + // rather than merely going missing from a view. Without a case of its own, deleting the + // guard in QbittorrentItemFetchWorkflow leaves every test in this file green. + [Theory] + [InlineData("600.5")] + [InlineData("\"600\"")] + [InlineData("6e2")] + public async Task GetItemsAsync_WhenOneTorrentIsUnreadable_DropsOnlyThatTorrent(string malformedDownloaded) + { + var apiMock = _provider.GetRequiredService(); + apiMock.InfoResponseOverride = QueueWithMalformedMiddleTorrent(malformedDownloaded); + var gateway = (DownloadClientGateway)_provider.GetRequiredService(); + var adapter = (QbittorrentAdapter)gateway.ResolveAdapter(_client); + + var items = await adapter.GetItemsAsync(_client); + + Assert.Contains(items, item => item.DownloadId == "aaaa1111"); + Assert.Contains(items, item => item.DownloadId == "cccc3333"); + Assert.DoesNotContain(items, item => item.DownloadId == "bbbb2222"); + Assert.Equal(2, items.Count); + } + + // The counterpart control for the guard above. The per-torrent files request lives inside + // the guarded block, so a client that stops answering after the torrent list arrives + // throws once per remaining torrent. If the guard swallowed those, a monitor poll would + // return a short queue and report success, and the monitor would neither back off nor say + // anything, which is a worse outcome than the truncation the guard was added to fix. + [Fact] + public async Task GetQueueAsync_WithIds_WhenTheClientStopsAnsweringMidPoll_StillFailsThePoll() + { + var apiMock = _provider.GetRequiredService(); + apiMock.InfoResponseOverride = QueueWithMalformedMiddleTorrent("500"); + apiMock.FilesRequestFailsAtTransport = true; + var gateway = (DownloadClientGateway)_provider.GetRequiredService(); + var adapter = (QbittorrentAdapter)gateway.ResolveAdapter(_client); + + await Assert.ThrowsAsync( + () => adapter.GetQueueAsync(_client, ["aaaa1111", "bbbb2222", "cccc3333"])); + } + + // The skip is a recurring condition, not an event. A torrent whose fields the mapper + // cannot read stays unreadable, so at the monitor's default cadence one such torrent + // writes a line on every poll for as long as it sits in the client. Warning would be + // asking the operator to act on something they cannot act on, so these two tests pin + // the level the way TransmissionQueueFetchWorkflow already logs the same condition. + [Fact] + public async Task GetQueueAsync_WhenOneTorrentIsUnreadable_LogsTheSkipAtDebug() + { + var logs = new RecordingLoggerProvider(); + Init(builder => builder + .WithSingleton(logs) + .WithMocks(RecordingLoggerProvider.CaptureEveryLevel)); + var apiMock = _provider.GetRequiredService(); + apiMock.InfoResponseOverride = QueueWithMalformedMiddleTorrent("\"600\""); + var gateway = (DownloadClientGateway)_provider.GetRequiredService(); + var adapter = (QbittorrentAdapter)gateway.ResolveAdapter(_client); + + await adapter.GetQueueAsync(_client); + + var skips = logs.EntriesContaining("Skipping unreadable qBittorrent torrent"); + Assert.NotEmpty(skips); + Assert.All(skips, entry => Assert.Equal(LogLevel.Debug, entry.Level)); + } + + [Fact] + public async Task GetItemsAsync_WhenOneTorrentIsUnreadable_LogsTheSkipAtDebug() + { + var logs = new RecordingLoggerProvider(); + Init(builder => builder + .WithSingleton(logs) + .WithMocks(RecordingLoggerProvider.CaptureEveryLevel)); + var apiMock = _provider.GetRequiredService(); + apiMock.InfoResponseOverride = QueueWithMalformedMiddleTorrent("\"600\""); + var gateway = (DownloadClientGateway)_provider.GetRequiredService(); + var adapter = (QbittorrentAdapter)gateway.ResolveAdapter(_client); + + await adapter.GetItemsAsync(_client); + + var skips = logs.EntriesContaining("Skipping unreadable qBittorrent torrent"); + Assert.NotEmpty(skips); + Assert.All(skips, entry => Assert.Equal(LogLevel.Debug, entry.Level)); + } + + // The hash is read out of the client's own JSON and then interpolated into the files + // query. The loop above now checks the token form of that value, so leaving the same + // value undefended one line later is the odd place to stop. With no escaping, a hash + // carrying an ampersand truncates at the delimiter and the client is asked about a + // torrent that does not exist, which returns an empty file list and no error. + [Fact] + public async Task GetQueueAsync_EscapesTheTorrentHashInTheFilesRequest() + { + var apiMock = _provider.GetRequiredService(); + apiMock.InfoResponseOverride = """ + [ + { + "hash": "aaaa1111&bbbb=2222", "name": "First", "progress": 0.5, "size": 1000, + "downloaded": 500, "state": "downloading", "save_path": "/downloads/a" + } + ] + """; + apiMock.ResetRequestHistory(); + var gateway = (DownloadClientGateway)_provider.GetRequiredService(); + var adapter = (QbittorrentAdapter)gateway.ResolveAdapter(_client); + + await adapter.GetQueueAsync(_client); + + var filesRequest = Assert.Single(apiMock.RequestHistory, + request => request.RequestUri.AbsolutePath.EndsWith("/api/v2/torrents/files", StringComparison.Ordinal)); + var query = HttpUtility.ParseQueryString(filesRequest.RequestUri.Query); + Assert.Equal("aaaa1111&bbbb=2222", query["hash"]); + } + + private sealed record RecordedLogEntry(LogLevel Level, string Message); + + // Enough of a logger to answer "at what level was this written", which nothing else in + // the suite needed until now. Registered as the only ILoggerProvider, so it sees every + // category including the adapter's. + private sealed class RecordingLoggerProvider : ILoggerProvider + { + private readonly object _gate = new(); + private readonly List _entries = []; + + // AddLogging() floors the factory at Information, so without this the Debug lines + // these tests exist to see would never reach a provider at all. + public static ServiceDescriptor CaptureEveryLevel { get; } = + ServiceDescriptor.Singleton>( + new Microsoft.Extensions.Options.ConfigureOptions( + options => options.MinLevel = LogLevel.Trace)); + + public ILogger CreateLogger(string categoryName) => new RecordingLogger(this); + + public IReadOnlyList EntriesContaining(string fragment) + { + lock (_gate) + { + return [.. _entries.Where(entry => entry.Message.Contains(fragment, StringComparison.Ordinal))]; + } + } + + public void Dispose() + { + } + + private void Record(LogLevel level, string message) + { + lock (_gate) + { + _entries.Add(new RecordedLogEntry(level, message)); + } + } + + private sealed class RecordingLogger(RecordingLoggerProvider owner) : ILogger + { + public IDisposable? BeginScope(TState state) where TState : notnull => null; + + public bool IsEnabled(LogLevel logLevel) => true; + + public void Log( + LogLevel logLevel, + EventId eventId, + TState state, + Exception? exception, + Func formatter) + { + ArgumentNullException.ThrowIfNull(formatter); + owner.Record(logLevel, formatter(state, exception)); + } + } + } + [Fact] public async Task MarkItemAsImportedAsync_SetsConfiguredPostImportCategory() { diff --git a/tests/Mocks/Api/QbittorrentApiMock.cs b/tests/Mocks/Api/QbittorrentApiMock.cs index f2845bc60..a1fad8139 100644 --- a/tests/Mocks/Api/QbittorrentApiMock.cs +++ b/tests/Mocks/Api/QbittorrentApiMock.cs @@ -13,6 +13,12 @@ public class QbittorrentApiMock : BaseApiMock public HttpStatusCode InfoStatusCode { get; set; } = HttpStatusCode.OK; public string? InfoResponseOverride { get; set; } + /// + /// Make the per-torrent files request fail at the transport layer, the way it does when + /// the client stops answering between the torrent list and the files calls that follow it. + /// + public bool FilesRequestFailsAtTransport { get; set; } + public QbittorrentApiMock() { AddRoute("api/v2/auth/login", DoLogin, HttpMethod.Post); @@ -88,6 +94,11 @@ private async Task GetFiles(HttpRequestMessage request, Can return new HttpResponseMessage(HttpStatusCode.Forbidden); } + if (FilesRequestFailsAtTransport) + { + throw new HttpRequestException("Connection refused"); + } + return MockUtils.GetCannedResponse("[]"); }