Additional logging when trying to complete tracked downloads

(cherry picked from commit 2df6b5370067635fdc9196451e09e4c2e6427eac)

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

@@ -3,6 +3,7 @@ using FizzWare.NBuilder;
 using FluentAssertions;
 using NUnit.Framework;
 using NzbDrone.Core.Books;
+using NzbDrone.Core.Download;
 using NzbDrone.Core.Download.TrackedDownloads;
 using NzbDrone.Core.History;
 using NzbDrone.Core.Parser.Model;
@@ -26,8 +27,11 @@ namespace NzbDrone.Core.Test.Download.TrackedDownloads
                                                       .With(r => r.Books = _books)
                                                       .Build();
 
+            var downloadItem = Builder<DownloadClientItem>.CreateNew().Build();
+
             _trackedDownload = Builder<TrackedDownload>.CreateNew()
                                                        .With(t => t.RemoteBook = remoteBook)
+                                                       .With(t => t.DownloadItem = downloadItem)
                                                        .Build();
 
             _historyItems = new List<EntityHistory>();

src/NzbDrone.Core/Download/CompletedDownloadService.cs

@@ -2,6 +2,7 @@ using System;
 using System.Collections.Generic;
 using System.IO;
 using System.Linq;
+using NLog;
 using NzbDrone.Common.EnvironmentInfo;
 using NzbDrone.Common.Extensions;
 using NzbDrone.Core.Books;
@@ -29,13 +30,15 @@ namespace NzbDrone.Core.Download
         private readonly IAuthorService _authorService;
         private readonly IProvideImportItemService _importItemService;
         private readonly ITrackedDownloadAlreadyImported _trackedDownloadAlreadyImported;
+        private readonly Logger _logger;
 
         public CompletedDownloadService(IEventAggregator eventAggregator,
                                         IHistoryService historyService,
                                         IProvideImportItemService importItemService,
                                         IDownloadedBooksImportService downloadedTracksImportService,
                                         IAuthorService authorService,
-                                        ITrackedDownloadAlreadyImported trackedDownloadAlreadyImported)
+                                        ITrackedDownloadAlreadyImported trackedDownloadAlreadyImported,
+                                        Logger logger)
         {
             _eventAggregator = eventAggregator;
             _historyService = historyService;
@@ -43,6 +46,7 @@ namespace NzbDrone.Core.Download
             _downloadedTracksImportService = downloadedTracksImportService;
             _authorService = authorService;
             _trackedDownloadAlreadyImported = trackedDownloadAlreadyImported;
+            _logger = logger;
         }
 
         public void Check(TrackedDownload trackedDownload)
@@ -129,6 +133,7 @@ namespace NzbDrone.Core.Download
 
             if (allItemsImported)
             {
+                _logger.Debug("All books were imported for {0}", trackedDownload.DownloadItem.Title);
                 trackedDownload.State = TrackedDownloadState.Imported;
 
                 var importedAuthorId = importResults.Where(x => x.Result == ImportResultType.Imported)
@@ -156,6 +161,7 @@ namespace NzbDrone.Core.Download
 
                 if (allEpisodesImportedInHistory)
                 {
+                    _logger.Debug("All books were imported in history for {0}", trackedDownload.DownloadItem.Title);
                     trackedDownload.State = TrackedDownloadState.Imported;
 
                     var importedAuthorId = historyItems.Where(x => x.EventType == EntityHistoryEventType.BookFileImported)
@@ -166,6 +172,7 @@ namespace NzbDrone.Core.Download
                 }
             }
 
+            _logger.Debug("Not all books 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<EntityHistory> historyItems)
         {
+            _logger.Trace("Checking if all books for '{0}' have been imported", trackedDownload.DownloadItem.Title);
+
             if (historyItems.Empty())
             {
+                _logger.Trace("No history for {0}", trackedDownload.DownloadItem.Title);
                 return false;
             }
 
@@ -30,12 +41,17 @@ namespace NzbDrone.Core.Download.TrackedDownloads
 
                 if (lastHistoryItem == null)
                 {
+                    _logger.Trace($"No history for book: {book}");
                     return false;
                 }
 
+                _logger.Trace($"Last event for book: {book} is: {lastHistoryItem.EventType}");
+
                 return lastHistoryItem.EventType == EntityHistoryEventType.BookFileImported;
             });
 
+            _logger.Trace("All books for '{0}' have been imported: {1}", trackedDownload.DownloadItem.Title, allBooksImportedInHistory);
+
             return allBooksImportedInHistory;
         }
     }

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

@@ -44,11 +44,13 @@ namespace NzbDrone.Core.MediaFiles.BookImport.Specifications
 
             if (lastImported == null)
             {
+                _logger.Trace("Book file has not been imported");
                 return Decision.Accept();
             }
 
             if (lastGrabbed != null && lastGrabbed.Date.After(lastImported.Date))
             {
+                _logger.Trace("Book file was grabbed again after importing");
                 return Decision.Accept();
             }