Additional logging when trying to complete tracked downloads

Co-Authored-By: Mark McDowall <markus101@users.noreply.github.com>

src/NzbDrone.Core.Test/Download/TrackedDownloads/TrackedDownloadAlreadyImportedFixture.cs

@@ -2,6 +2,7 @@ using System.Collections.Generic;
 using FizzWare.NBuilder;
 using FluentAssertions;
 using NUnit.Framework;
+using NzbDrone.Core.Download;
 using NzbDrone.Core.Download.TrackedDownloads;
 using NzbDrone.Core.History;
 using NzbDrone.Core.Movies;
@@ -26,8 +27,12 @@ namespace NzbDrone.Core.Test.Download.TrackedDownloads
                                                       .With(r => r.Movie = _movie)
                                                       .Build();
 
+            var downloadItem = Builder<DownloadClientItem>.CreateNew()
+                                                         .Build();
+
             _trackedDownload = Builder<TrackedDownload>.CreateNew()
                                                        .With(t => t.RemoteMovie = remoteMovie)
+                                                       .With(t => t.DownloadItem = downloadItem)
                                                        .Build();
 
             _historyItems = new List<MovieHistory>();

src/NzbDrone.Core/Download/CompletedDownloadService.cs

@@ -1,6 +1,7 @@
 using System.Collections.Generic;
 using System.IO;
 using System.Linq;
+using NLog;
 using NzbDrone.Common.EnvironmentInfo;
 using NzbDrone.Common.Extensions;
 using NzbDrone.Core.Download.TrackedDownloads;
@@ -28,13 +29,15 @@ namespace NzbDrone.Core.Download
         private readonly IParsingService _parsingService;
         private readonly IMovieService _movieService;
         private readonly ITrackedDownloadAlreadyImported _trackedDownloadAlreadyImported;
+        private readonly Logger _logger;
 
         public CompletedDownloadService(IEventAggregator eventAggregator,
                                         IHistoryService historyService,
                                         IDownloadedMovieImportService downloadedMovieImportService,
                                         IParsingService parsingService,
                                         IMovieService movieService,
-                                        ITrackedDownloadAlreadyImported trackedDownloadAlreadyImported)
+                                        ITrackedDownloadAlreadyImported trackedDownloadAlreadyImported,
+                                        Logger logger)
         {
             _eventAggregator = eventAggregator;
             _historyService = historyService;
@@ -42,6 +45,7 @@ namespace NzbDrone.Core.Download
             _parsingService = parsingService;
             _movieService = movieService;
             _trackedDownloadAlreadyImported = trackedDownloadAlreadyImported;
+            _logger = logger;
         }
 
         public void Check(TrackedDownload trackedDownload)
@@ -137,6 +141,7 @@ namespace NzbDrone.Core.Download
 
             if (allMoviesImported)
             {
+                _logger.Debug("All movies were imported for {0}", trackedDownload.DownloadItem.Title);
                 trackedDownload.State = TrackedDownloadState.Imported;
                 _eventAggregator.PublishEvent(new DownloadCompletedEvent(trackedDownload, trackedDownload.RemoteMovie.Movie.Id));
                 return true;
@@ -155,12 +160,14 @@ namespace NzbDrone.Core.Download
 
                 if (allMoviesImportedInHistory)
                 {
+                    _logger.Debug("All movies were imported in history for {0}", trackedDownload.DownloadItem.Title);
                     trackedDownload.State = TrackedDownloadState.Imported;
                     _eventAggregator.PublishEvent(new DownloadCompletedEvent(trackedDownload, trackedDownload.RemoteMovie.Movie.Id));
                     return true;
                 }
             }
 
+            _logger.Debug("Not all movies have been imported for {0}", trackedDownload.DownloadItem.Title);
             return false;
         }
     }

src/NzbDrone.Core/Download/TrackedDownloads/TrackedDownloadAlreadyImported.cs

@@ -1,5 +1,6 @@
 using System.Collections.Generic;
 using System.Linq;
+using NLog;
 using NzbDrone.Common.Extensions;
 using NzbDrone.Core.History;
 
@@ -12,10 +13,20 @@ namespace NzbDrone.Core.Download.TrackedDownloads
 
     public class TrackedDownloadAlreadyImported : ITrackedDownloadAlreadyImported
     {
+        private readonly Logger _logger;
+
+        public TrackedDownloadAlreadyImported(Logger logger)
+        {
+            _logger = logger;
+        }
+
         public bool IsImported(TrackedDownload trackedDownload, List<MovieHistory> historyItems)
         {
+            _logger.Trace("Checking if all movies for '{0}' have been imported", trackedDownload.DownloadItem.Title);
+
             if (historyItems.Empty())
             {
+                _logger.Trace("No history for {0}", trackedDownload.DownloadItem.Title);
                 return false;
             }
 
@@ -25,11 +36,14 @@ namespace NzbDrone.Core.Download.TrackedDownloads
 
             if (lastHistoryItem == null)
             {
+                _logger.Trace("No history for movie: {0}", movie.ToString());
                 return false;
             }
 
             var allMoviesImportedInHistory = lastHistoryItem.EventType == MovieHistoryEventType.DownloadFolderImported;
+            _logger.Trace("Last event for movie: {0} is: {1}", movie, lastHistoryItem.EventType);
 
+            _logger.Trace("All movies for '{0}' have been imported: {1}", trackedDownload.DownloadItem.Title, allMoviesImportedInHistory);
             return allMoviesImportedInHistory;
         }
     }

src/NzbDrone.Core/MediaFiles/MovieImport/Specifications/AlreadyImportedSpecification.cs

@@ -44,12 +44,14 @@ namespace NzbDrone.Core.MediaFiles.MovieImport.Specifications
 
             if (lastImported == null)
             {
+                _logger.Trace("Movie file has not been imported");
                 return Decision.Accept();
             }
 
             // If the release was grabbed again after importing don't reject it
             if (lastGrabbed != null && lastGrabbed.Date.After(lastImported.Date))
             {
+                _logger.Trace("Movie file was grabbed again after importing");
                 return Decision.Accept();
             }