search

rmcrackan / Libation

Libation: Liberate your Library
GNU General Public License v3.0
2.69k stars 147 forks source link

Crash when saving to NFS directory #219

Closed pixil98 closed 2 years ago

pixil98 commented 2 years ago

I setup Libation to save directly to the NFS share that my Plex server is running on. Every time I try to liberate a book it crashes after copying the m4b file to the NFS share. It doesn't seem to matter which book I try downloading.

Here are the logs:

2022-03-29 08:29:32.311 -05:00 [INF] (at AppScaffolding.LibationScaffolding.logStartupState(LibationFileManager.Configuration)) 

 {}2022-03-29 08:29:32.355 -05:00 [INF] (at AppScaffolding.LibationScaffolding.logStartupState(LibationFileManager.Configuration)) Begin. {"AppName":"Libation","Version":"6.7.3.2","Mode":"Release","LogLevel_Verbose_Enabled":false,"LogLevel_Debug_Enabled":true,"LogLevel_Information_Enabled":true,"LogLevel_Warning_Enabled":true,"LogLevel_Error_Enabled":true,"LogLevel_Fatal_Enabled":true,"LibationFiles":"C:\\Users\\aaron\\Libation","BooksDirectory":"E:\\audible","InProgress":".\\LibationFiles","DownloadsInProgressDirectory":"E:\\Libation.6.7.3\\LibationFiles\\DownloadsInProgress","DownloadsInProgressFiles":0,"DecryptInProgressDirectory":"E:\\Libation.6.7.3\\LibationFiles\\DecryptInProgress","DecryptInProgressFiles":4}
 {}2022-03-29 08:29:36.142 -05:00 [DBG] (at LibationSearchEngine.SearchEngine.Search(System.String)) original search string: {"searchString":null}
 {}2022-03-29 08:29:36.145 -05:00 [DBG] (at LibationSearchEngine.SearchEngine.Search(System.String)) formatted search string: {"searchString":"*:*"}
 {}2022-03-29 08:29:36.276 -05:00 [DBG] (at LibationSearchEngine.SearchEngine.generalSearch(System.String)) query: {"queryString":"*:*"}
 {}2022-03-29 08:29:36.290 -05:00 [DBG] (at LibationSearchEngine.SearchEngine.Search(System.String)) Hit(s): {"count":772}
 {}2022-03-29 08:29:36.464 -05:00 [DBG] (at LibationSearchEngine.SearchEngine.Search(System.String)) original search string: {"searchString":""}
 {}2022-03-29 08:29:36.466 -05:00 [DBG] (at LibationSearchEngine.SearchEngine.Search(System.String)) formatted search string: {"searchString":"*:*"}
 {}2022-03-29 08:29:36.508 -05:00 [DBG] (at LibationSearchEngine.SearchEngine.generalSearch(System.String)) query: {"queryString":"*:*"}
 {}2022-03-29 08:29:36.510 -05:00 [DBG] (at LibationSearchEngine.SearchEngine.Search(System.String)) Hit(s): {"count":772}
 {}2022-03-29 08:29:36.969 -05:00 [INF] (at ApplicationServices.LibraryCommands.GetCounts()) Book counts. {"total":772,"booksFullyBackedUp":771,"booksDownloadedOnly":0,"booksNoProgress":1,"booksError":0}
 {}2022-03-29 08:29:36.984 -05:00 [INF] (at ApplicationServices.LibraryCommands.GetCounts()) PDF counts. {"total":31,"pdfsDownloaded":31,"pdfsNotDownloaded":0}
 {}2022-03-29 08:29:49.702 -05:00 [INF] (at FileManager.PersistentDictionary.writeFile(System.String, Newtonsoft.Json.Linq.JToken)) Config changed. {"propertyName":"Books","newValue":"P:\\audible"}
 {}2022-03-29 08:29:49.705 -05:00 [DBG] (at LibationFileManager.Configuration.set_LogLevel(Serilog.Events.LogEventLevel)) LogLevel.set attempt. No change
 {}2022-03-29 08:30:16.929 -05:00 [DBG] (at LibationSearchEngine.SearchEngine.Search(System.String)) original search string: {"searchString":""}
 {}2022-03-29 08:30:16.934 -05:00 [DBG] (at LibationSearchEngine.SearchEngine.Search(System.String)) formatted search string: {"searchString":"*:*"}
 {}2022-03-29 08:30:16.973 -05:00 [DBG] (at LibationSearchEngine.SearchEngine.generalSearch(System.String)) query: {"queryString":"*:*"}
 {}2022-03-29 08:30:16.975 -05:00 [DBG] (at LibationSearchEngine.SearchEngine.Search(System.String)) Hit(s): {"count":772}
 {}2022-03-29 08:30:17.211 -05:00 [INF] (at ApplicationServices.LibraryCommands.GetCounts()) Book counts. {"total":772,"booksFullyBackedUp":770,"booksDownloadedOnly":0,"booksNoProgress":2,"booksError":0}
 {}2022-03-29 08:30:17.212 -05:00 [INF] (at ApplicationServices.LibraryCommands.GetCounts()) PDF counts. {"total":31,"pdfsDownloaded":31,"pdfsNotDownloaded":0}
 {}2022-03-29 08:30:18.057 -05:00 [INF] (at LibationWinForms.BookLiberation.ProcessorAutomationController+<BackupSingleBookAsync>d__0.MoveNext()) Begin BackupSingleBookAsync {"AudibleProductId":"B09PSLLWFG"}
 {}2022-03-29 08:30:18.067 -05:00 [INF] (at FileLiberator.Processable+<ProcessSingleAsync>d__12.MoveNext()) Begin ProcessSingleAsync {"Title":"Impact Winter","AudibleProductId":"B09PSLLWFG","Locale":"us","Account":"[...]"}
 {}2022-03-29 08:30:18.078 -05:00 [DBG] (at FileLiberator.Processable.OnBegin(DataLayer.LibraryBook)) Event fired {"Name":"Begin","Book":["B09PSLLWFG","Impact Winter","us","[...]"]}
 {}2022-03-29 08:30:18.092 -05:00 [INF] (at LibationWinForms.BookLiberation.LogMe+<>c.<.ctor>b__9_0(System.Object, System.String)) Automated backup: Download & Decrypt Step, Begin: [B09PSLLWFG] Impact Winter
 {}2022-03-29 08:30:18.105 -05:00 [DBG] (at FileLiberator.Streamable.OnStreamingBegin(System.String)) Event fired {"Name":"StreamingBegin","Message":"Begin decrypting 3/29/2022 [B09PSLLWFG] Impact Winter"}
 {}2022-03-29 08:30:18.131 -05:00 [INF] (at AudibleUtilities.ApiExtended+<CreateAsync>d__9.MoveNext()) {"Username":"[...]","LocaleName":"us"}
 {}2022-03-29 08:30:18.680 -05:00 [INF] (at Dinah.Core.StepRunner.BaseStep.logBegin()) Begin step 'Download and Convert Aaxc To M4b'
 {}2022-03-29 08:30:18.681 -05:00 [INF] (at Dinah.Core.StepRunner.BaseStep.logBegin()) Begin step 'Step 1: Get Aaxc Metadata'
 {}2022-03-29 08:30:19.660 -05:00 [DBG] (at FileLiberator.AudioDecodable.OnTitleDiscovered(System.String)) Event fired {"Name":"TitleDiscovered","Title":"Impact Winter"}
 {}2022-03-29 08:30:19.661 -05:00 [DBG] (at FileLiberator.AudioDecodable.OnAuthorsDiscovered(System.String)) Event fired {"Name":"AuthorsDiscovered","Authors":"Travis Beacham"}
 {}2022-03-29 08:30:19.662 -05:00 [DBG] (at FileLiberator.AudioDecodable.OnNarratorsDiscovered(System.String)) Event fired {"Name":"NarratorsDiscovered","Narrators":"full cast"}
 {}2022-03-29 08:30:19.664 -05:00 [DBG] (at FileLiberator.AudioDecodable.OnCoverImageDiscovered(System.Byte[])) Event fired {"Name":"CoverImageDiscovered","CoverImageBytes":58481}
 {}2022-03-29 08:30:19.665 -05:00 [INF] (at Dinah.Core.StepRunner.BaseStep.logEnd(System.Boolean, System.TimeSpan, System.Exception)) End step 'Step 1: Get Aaxc Metadata'. Success. Completed in 00:00:00
 {}2022-03-29 08:30:19.666 -05:00 [INF] (at Dinah.Core.StepRunner.BaseStep.logBegin()) Begin step 'Step 2: Download Decrypted Audiobook'
 {}2022-03-29 08:31:07.252 -05:00 [INF] (at FileLiberator.Streamable.OnFileCreated(System.String, System.String)) File created {"Name":"FileCreated","id":"B09PSLLWFG","path":"E:\\Libation.6.7.3\\LibationFiles\\DecryptInProgress\\Impact Winter [B09PSLLWFG].m4b"}
 {}2022-03-29 08:31:07.263 -05:00 [INF] (at Dinah.Core.StepRunner.BaseStep.logEnd(System.Boolean, System.TimeSpan, System.Exception)) End step 'Step 2: Download Decrypted Audiobook'. Success. Completed in 00:00:47
 {}2022-03-29 08:31:07.264 -05:00 [INF] (at Dinah.Core.StepRunner.BaseStep.logBegin()) Begin step 'Step 3: Create Cue'
 {}2022-03-29 08:31:07.267 -05:00 [INF] (at FileLiberator.Streamable.OnFileCreated(System.String, System.String)) File created {"Name":"FileCreated","id":"B09PSLLWFG","path":"E:\\Libation.6.7.3\\LibationFiles\\DecryptInProgress\\Impact Winter [B09PSLLWFG].cue"}
 {}2022-03-29 08:31:07.278 -05:00 [INF] (at Dinah.Core.StepRunner.BaseStep.logEnd(System.Boolean, System.TimeSpan, System.Exception)) End step 'Step 3: Create Cue'. Success. Completed in 00:00:00
 {}2022-03-29 08:31:07.279 -05:00 [INF] (at Dinah.Core.StepRunner.BaseStep.logBegin()) Begin step 'Step 4: Cleanup'
 {}2022-03-29 08:31:07.281 -05:00 [INF] (at FileManager.FileUtility+<>c__DisplayClass32_0.<SaferDelete>b__0()) File successfully deleted
 {}2022-03-29 08:31:07.312 -05:00 [INF] (at FileManager.FileUtility+<>c__DisplayClass32_0.<SaferDelete>b__0()) File successfully deleted
 {}2022-03-29 08:31:07.313 -05:00 [INF] (at Dinah.Core.StepRunner.BaseStep.logEnd(System.Boolean, System.TimeSpan, System.Exception)) End step 'Step 4: Cleanup'. Success. Completed in 00:00:00
 {}2022-03-29 08:31:07.314 -05:00 [INF] (at Dinah.Core.StepRunner.BaseStep.logEnd(System.Boolean, System.TimeSpan, System.Exception)) End step 'Download and Convert Aaxc To M4b'. Success. Completed in 00:00:48
 {}2022-03-29 08:31:07.314 -05:00 [DBG] (at FileLiberator.Streamable.OnStreamingCompleted(System.String)) Event fired {"Name":"StreamingCompleted","Message":"Completed downloading and decrypting Impact Winter"}
 {}
rmcrackan commented 2 years ago

Sorry it's crashing. Nothing here looks like a problem so I guess it's happening somehow outside of what can create log entries. I can't think of what that might be. Are there additional errors shown when it crashes? Or does it just vanish from task manager without warning?

Let's delete the files in the "in progress" folders. They shouldn't be a problem but let's stack the deck in our favor, just in case E:\Libation.6.7.3\LibationFiles\DownloadsInProgress and E:\Libation.6.7.3\LibationFiles\DecryptInProgress

There can be possible file conflicts if any of the places that Libation writes files to (in progress, or the 'books' directory) are also live backed up by dropbox, icloud, gdrive, etc. It doesn't come up often anymore (I actually save directly to dropbox all the time and almost never have issues) but it's a possible pain point. You can change these directories in Settings.

I assume C is your computer and E is your network map. There should be no issue using your network drive however you wish -- Windows itself takes care of the particulars. However since something is going wrong, maybe try moving Libation to C, saving in progress files directories to C and only setting your books output directory as E.

If my reply seems like rambling guesses, you're right. This shouldn't be happening so I'm grasping at debugging hunches. Let me know if anything helps.

pixil98 commented 2 years ago

No problem, I'm happy to help debug it. When it crashes I don't get any errors, after copying the m4b file over it just vanishes. I should clarify the various drives i have: C: is the internal nvme storage E: is a USB drive I'm running Libation from so I don't write gigabytes of tmp data to the nvme drive P: is the NFS share that is configured as the ultimate destination (doesn't show up in the logs anywhere)

Previously I'd been writing to an SMB share using this exact setup and it worked fine. I can eliminate the USB drive from the setup tonight and try again. If you have anything else you'd like me to test let me know.

rmcrackan commented 2 years ago

Thanks. Let me know how that works tonight. It's cool if you don't want to use C; let's just get it in a working state then change one variable at a time.

Ah, you must be using a custom template to redirect output to P. Can you share those templates? Since the files are getting moved correctly, I don't see how it could cause this error. I'd like to look though so we can eliminate this as a culprit.

The 'just vanishing' thing is mind-boggling. Any error during your download/decrypt should be caught and logged. Only something as extreme as out of disk or out of memory should act like that and you would see all kinds of other not subtle symptoms on your system if that were the case.

pixil98 commented 2 years ago

I'm not sure what you mean by a custom template. I've just set the Books location in settings and then in Download/Decrypt I have the in progress files set to the same location that Libation is running from. image

I don't think there is a problem during download/decrypt. When I check the In progress folder both the m4b and the cue file are there. It seems to crash during/after copying the m4b file over to the NFS share but before it copies the cue file.

I moved Libation to C:\Libation.6.7.3 and still run into the same problem. Here are the logs on the off chance they show something different:

2022-03-29 16:56:49.915 -05:00 [INF] (at AppScaffolding.LibationScaffolding.logStartupState(LibationFileManager.Configuration)) 

 {}2022-03-29 16:56:49.962 -05:00 [INF] (at AppScaffolding.LibationScaffolding.logStartupState(LibationFileManager.Configuration)) Begin. {"AppName":"Libation","Version":"6.7.3.2","Mode":"Release","LogLevel_Verbose_Enabled":false,"LogLevel_Debug_Enabled":true,"LogLevel_Information_Enabled":true,"LogLevel_Warning_Enabled":true,"LogLevel_Error_Enabled":true,"LogLevel_Fatal_Enabled":true,"LibationFiles":"C:\\Users\\aaron\\Libation","BooksDirectory":"P:\\audible","InProgress":".\\LibationFiles","DownloadsInProgressDirectory":"C:\\Libation.6.7.3\\LibationFiles\\DownloadsInProgress","DownloadsInProgressFiles":0,"DecryptInProgressDirectory":"C:\\Libation.6.7.3\\LibationFiles\\DecryptInProgress","DecryptInProgressFiles":0}
 {}2022-03-29 16:56:52.706 -05:00 [DBG] (at LibationSearchEngine.SearchEngine.Search(System.String)) original search string: {"searchString":null}
 {}2022-03-29 16:56:52.708 -05:00 [DBG] (at LibationSearchEngine.SearchEngine.Search(System.String)) formatted search string: {"searchString":"*:*"}
 {}2022-03-29 16:56:52.832 -05:00 [DBG] (at LibationSearchEngine.SearchEngine.generalSearch(System.String)) query: {"queryString":"*:*"}
 {}2022-03-29 16:56:52.841 -05:00 [DBG] (at LibationSearchEngine.SearchEngine.Search(System.String)) Hit(s): {"count":772}
 {}2022-03-29 16:56:52.913 -05:00 [DBG] (at LibationSearchEngine.SearchEngine.Search(System.String)) original search string: {"searchString":""}
 {}2022-03-29 16:56:52.915 -05:00 [DBG] (at LibationSearchEngine.SearchEngine.Search(System.String)) formatted search string: {"searchString":"*:*"}
 {}2022-03-29 16:56:52.954 -05:00 [DBG] (at LibationSearchEngine.SearchEngine.generalSearch(System.String)) query: {"queryString":"*:*"}
 {}2022-03-29 16:56:52.956 -05:00 [DBG] (at LibationSearchEngine.SearchEngine.Search(System.String)) Hit(s): {"count":772}
 {}2022-03-29 16:56:54.454 -05:00 [INF] (at ApplicationServices.LibraryCommands.GetCounts()) Book counts. {"total":772,"booksFullyBackedUp":771,"booksDownloadedOnly":0,"booksNoProgress":1,"booksError":0}
 {}2022-03-29 16:56:54.471 -05:00 [INF] (at ApplicationServices.LibraryCommands.GetCounts()) PDF counts. {"total":31,"pdfsDownloaded":31,"pdfsNotDownloaded":0}
 {}2022-03-29 16:57:01.869 -05:00 [DBG] (at LibationSearchEngine.SearchEngine.Search(System.String)) original search string: {"searchString":""}
 {}2022-03-29 16:57:01.871 -05:00 [DBG] (at LibationSearchEngine.SearchEngine.Search(System.String)) formatted search string: {"searchString":"*:*"}
 {}2022-03-29 16:57:01.921 -05:00 [DBG] (at LibationSearchEngine.SearchEngine.generalSearch(System.String)) query: {"queryString":"*:*"}
 {}2022-03-29 16:57:01.923 -05:00 [DBG] (at LibationSearchEngine.SearchEngine.Search(System.String)) Hit(s): {"count":772}
 {}2022-03-29 16:57:02.140 -05:00 [INF] (at ApplicationServices.LibraryCommands.GetCounts()) Book counts. {"total":772,"booksFullyBackedUp":770,"booksDownloadedOnly":0,"booksNoProgress":2,"booksError":0}
 {}2022-03-29 16:57:02.141 -05:00 [INF] (at ApplicationServices.LibraryCommands.GetCounts()) PDF counts. {"total":31,"pdfsDownloaded":31,"pdfsNotDownloaded":0}
 {}2022-03-29 16:57:16.163 -05:00 [INF] (at LibationWinForms.BookLiberation.ProcessorAutomationController+<BackupSingleBookAsync>d__0.MoveNext()) Begin BackupSingleBookAsync {"AudibleProductId":"B09PSLLWFG"}
 {}2022-03-29 16:57:16.173 -05:00 [INF] (at FileLiberator.Processable+<ProcessSingleAsync>d__12.MoveNext()) Begin ProcessSingleAsync {"Title":"Impact Winter","AudibleProductId":"B09PSLLWFG","Locale":"us","Account":"[...]"}
 {}2022-03-29 16:57:16.178 -05:00 [DBG] (at FileLiberator.Processable.OnBegin(DataLayer.LibraryBook)) Event fired {"Name":"Begin","Book":["B09PSLLWFG","Impact Winter","us","[...]"]}
 {}2022-03-29 16:57:16.189 -05:00 [INF] (at LibationWinForms.BookLiberation.LogMe+<>c.<.ctor>b__9_0(System.Object, System.String)) Automated backup: Download & Decrypt Step, Begin: [B09PSLLWFG] Impact Winter
 {}2022-03-29 16:57:16.305 -05:00 [DBG] (at FileLiberator.Streamable.OnStreamingBegin(System.String)) Event fired {"Name":"StreamingBegin","Message":"Begin decrypting 3/29/2022 [B09PSLLWFG] Impact Winter"}
 {}2022-03-29 16:57:16.335 -05:00 [INF] (at AudibleUtilities.ApiExtended+<CreateAsync>d__9.MoveNext()) {"Username":"[...]","LocaleName":"us"}
 {}2022-03-29 16:57:17.716 -05:00 [INF] (at Dinah.Core.StepRunner.BaseStep.logBegin()) Begin step 'Download and Convert Aaxc To M4b'
 {}2022-03-29 16:57:17.718 -05:00 [INF] (at Dinah.Core.StepRunner.BaseStep.logBegin()) Begin step 'Step 1: Get Aaxc Metadata'
 {}2022-03-29 16:57:18.857 -05:00 [DBG] (at FileLiberator.AudioDecodable.OnTitleDiscovered(System.String)) Event fired {"Name":"TitleDiscovered","Title":"Impact Winter"}
 {}2022-03-29 16:57:18.858 -05:00 [DBG] (at FileLiberator.AudioDecodable.OnAuthorsDiscovered(System.String)) Event fired {"Name":"AuthorsDiscovered","Authors":"Travis Beacham"}
 {}2022-03-29 16:57:18.860 -05:00 [DBG] (at FileLiberator.AudioDecodable.OnNarratorsDiscovered(System.String)) Event fired {"Name":"NarratorsDiscovered","Narrators":"full cast"}
 {}2022-03-29 16:57:18.861 -05:00 [DBG] (at FileLiberator.AudioDecodable.OnCoverImageDiscovered(System.Byte[])) Event fired {"Name":"CoverImageDiscovered","CoverImageBytes":58481}
 {}2022-03-29 16:57:18.862 -05:00 [INF] (at Dinah.Core.StepRunner.BaseStep.logEnd(System.Boolean, System.TimeSpan, System.Exception)) End step 'Step 1: Get Aaxc Metadata'. Success. Completed in 00:00:01
 {}2022-03-29 16:57:18.862 -05:00 [INF] (at Dinah.Core.StepRunner.BaseStep.logBegin()) Begin step 'Step 2: Download Decrypted Audiobook'
 {}2022-03-29 16:58:03.762 -05:00 [INF] (at FileLiberator.Streamable.OnFileCreated(System.String, System.String)) File created {"Name":"FileCreated","id":"B09PSLLWFG","path":"C:\\Libation.6.7.3\\LibationFiles\\DecryptInProgress\\Impact Winter [B09PSLLWFG].m4b"}
 {}2022-03-29 16:58:03.775 -05:00 [INF] (at Dinah.Core.StepRunner.BaseStep.logEnd(System.Boolean, System.TimeSpan, System.Exception)) End step 'Step 2: Download Decrypted Audiobook'. Success. Completed in 00:00:44
 {}2022-03-29 16:58:03.776 -05:00 [INF] (at Dinah.Core.StepRunner.BaseStep.logBegin()) Begin step 'Step 3: Create Cue'
 {}2022-03-29 16:58:03.779 -05:00 [INF] (at FileLiberator.Streamable.OnFileCreated(System.String, System.String)) File created {"Name":"FileCreated","id":"B09PSLLWFG","path":"C:\\Libation.6.7.3\\LibationFiles\\DecryptInProgress\\Impact Winter [B09PSLLWFG].cue"}
 {}2022-03-29 16:58:03.790 -05:00 [INF] (at Dinah.Core.StepRunner.BaseStep.logEnd(System.Boolean, System.TimeSpan, System.Exception)) End step 'Step 3: Create Cue'. Success. Completed in 00:00:00
 {}2022-03-29 16:58:03.790 -05:00 [INF] (at Dinah.Core.StepRunner.BaseStep.logBegin()) Begin step 'Step 4: Cleanup'
 {}2022-03-29 16:58:03.791 -05:00 [INF] (at FileManager.FileUtility+<>c__DisplayClass32_0.<SaferDelete>b__0()) File successfully deleted
 {}2022-03-29 16:58:03.818 -05:00 [INF] (at FileManager.FileUtility+<>c__DisplayClass32_0.<SaferDelete>b__0()) File successfully deleted
 {}2022-03-29 16:58:03.819 -05:00 [INF] (at Dinah.Core.StepRunner.BaseStep.logEnd(System.Boolean, System.TimeSpan, System.Exception)) End step 'Step 4: Cleanup'. Success. Completed in 00:00:00
 {}2022-03-29 16:58:03.820 -05:00 [INF] (at Dinah.Core.StepRunner.BaseStep.logEnd(System.Boolean, System.TimeSpan, System.Exception)) End step 'Download and Convert Aaxc To M4b'. Success. Completed in 00:00:46
 {}2022-03-29 16:58:03.820 -05:00 [DBG] (at FileLiberator.Streamable.OnStreamingCompleted(System.String)) Event fired {"Name":"StreamingCompleted","Message":"Completed downloading and decrypting Impact Winter"}
 {}2022-03-29 16:58:03.826 -05:00 [INF] (at FileManager.PersistentDictionary.writeFile(System.String, Newtonsoft.Json.Linq.JToken)) Config changed. {"propertyName":"DecryptForm","newValue":"{\r\n  \"X\": 596,\r\n  \"Y\": 117,\r\n  \"Height\": 221,\r\n  \"Width\": 723,\r\n  \"IsMaximized\": false\r\n}"}
 {}
rmcrackan commented 2 years ago

I just released a new version with additional logging around file moving. It will only show up in the log when logging is set to Debug. Let's see if that tells us anything

pixil98 commented 2 years ago

Here are the logs. I also noticed that the m4b file it copies is missing the ID3 tags so it looks like it's crashing mid copy. If I copy the file from DecryptInProgress over by hand it retains the tags.

2022-03-30 09:52:40.617 -05:00 [INF] (at AppScaffolding.LibationScaffolding.logStartupState(LibationFileManager.Configuration)) 

 {}2022-03-30 09:52:40.661 -05:00 [INF] (at AppScaffolding.LibationScaffolding.logStartupState(LibationFileManager.Configuration)) Begin. {"AppName":"Libation","Version":"6.7.4.2","Mode":"Release","LogLevel_Verbose_Enabled":false,"LogLevel_Debug_Enabled":true,"LogLevel_Information_Enabled":true,"LogLevel_Warning_Enabled":true,"LogLevel_Error_Enabled":true,"LogLevel_Fatal_Enabled":true,"LibationFiles":"C:\\Users\\aaron\\Libation","BooksDirectory":"P:\\audible","InProgress":".\\LibationFiles","DownloadsInProgressDirectory":"C:\\Libation.6.7.4\\LibationFiles\\DownloadsInProgress","DownloadsInProgressFiles":0,"DecryptInProgressDirectory":"C:\\Libation.6.7.4\\LibationFiles\\DecryptInProgress","DecryptInProgressFiles":0}
 {}2022-03-30 09:52:43.378 -05:00 [DBG] (at LibationSearchEngine.SearchEngine.Search(System.String)) original search string: {"searchString":null}
 {}2022-03-30 09:52:43.381 -05:00 [DBG] (at LibationSearchEngine.SearchEngine.Search(System.String)) formatted search string: {"searchString":"*:*"}
 {}2022-03-30 09:52:43.503 -05:00 [DBG] (at LibationSearchEngine.SearchEngine.generalSearch(System.String)) query: {"queryString":"*:*"}
 {}2022-03-30 09:52:43.512 -05:00 [DBG] (at LibationSearchEngine.SearchEngine.Search(System.String)) Hit(s): {"count":772}
 {}2022-03-30 09:52:43.600 -05:00 [DBG] (at LibationSearchEngine.SearchEngine.Search(System.String)) original search string: {"searchString":""}
 {}2022-03-30 09:52:43.602 -05:00 [DBG] (at LibationSearchEngine.SearchEngine.Search(System.String)) formatted search string: {"searchString":"*:*"}
 {}2022-03-30 09:52:43.635 -05:00 [DBG] (at LibationSearchEngine.SearchEngine.generalSearch(System.String)) query: {"queryString":"*:*"}
 {}2022-03-30 09:52:43.637 -05:00 [DBG] (at LibationSearchEngine.SearchEngine.Search(System.String)) Hit(s): {"count":772}
 {}2022-03-30 09:52:44.163 -05:00 [INF] (at ApplicationServices.LibraryCommands.GetCounts()) Book counts. {"total":772,"booksFullyBackedUp":770,"booksDownloadedOnly":0,"booksNoProgress":2,"booksError":0}
 {}2022-03-30 09:52:44.178 -05:00 [INF] (at ApplicationServices.LibraryCommands.GetCounts()) PDF counts. {"total":31,"pdfsDownloaded":31,"pdfsNotDownloaded":0}
 {}2022-03-30 09:52:45.709 -05:00 [INF] (at LibationWinForms.BookLiberation.ProcessorAutomationController+<BackupSingleBookAsync>d__0.MoveNext()) Begin BackupSingleBookAsync {"AudibleProductId":"B09PSLLWFG"}
 {}2022-03-30 09:52:45.720 -05:00 [INF] (at FileLiberator.Processable+<ProcessSingleAsync>d__12.MoveNext()) Begin ProcessSingleAsync {"Title":"Impact Winter","AudibleProductId":"B09PSLLWFG","Locale":"us","Account":"[...]"}
 {}2022-03-30 09:52:45.724 -05:00 [DBG] (at FileLiberator.Processable.OnBegin(DataLayer.LibraryBook)) Event fired {"Name":"Begin","Book":["B09PSLLWFG","Impact Winter","us","[...]"]}
 {}2022-03-30 09:52:45.802 -05:00 [INF] (at LibationWinForms.BookLiberation.LogMe+<>c.<.ctor>b__9_0(System.Object, System.String)) Automated backup: Download & Decrypt Step, Begin: [B09PSLLWFG] Impact Winter
 {}2022-03-30 09:52:45.915 -05:00 [DBG] (at FileLiberator.Streamable.OnStreamingBegin(System.String)) Event fired {"Name":"StreamingBegin","Message":"Begin decrypting 3/29/2022 [B09PSLLWFG] Impact Winter"}
 {}2022-03-30 09:52:45.956 -05:00 [INF] (at AudibleUtilities.ApiExtended+<CreateAsync>d__9.MoveNext()) {"Username":"[...]","LocaleName":"us"}
 {}2022-03-30 09:52:47.211 -05:00 [DBG] (at FileManager.FileUtility+<>c__DisplayClass32_0.<SaferDelete>b__0()) No file to delete: {"source":"C:\\Libation.6.7.4\\LibationFiles\\DecryptInProgress\\Impact Winter [B09PSLLWFG].m4b"}
 {}2022-03-30 09:52:47.217 -05:00 [INF] (at Dinah.Core.StepRunner.BaseStep.logBegin()) Begin step 'Download and Convert Aaxc To M4b'
 {}2022-03-30 09:52:47.218 -05:00 [INF] (at Dinah.Core.StepRunner.BaseStep.logBegin()) Begin step 'Step 1: Get Aaxc Metadata'
 {}2022-03-30 09:52:48.312 -05:00 [DBG] (at FileLiberator.AudioDecodable.OnTitleDiscovered(System.String)) Event fired {"Name":"TitleDiscovered","Title":"Impact Winter"}
 {}2022-03-30 09:52:48.314 -05:00 [DBG] (at FileLiberator.AudioDecodable.OnAuthorsDiscovered(System.String)) Event fired {"Name":"AuthorsDiscovered","Authors":"Travis Beacham"}
 {}2022-03-30 09:52:48.315 -05:00 [DBG] (at FileLiberator.AudioDecodable.OnNarratorsDiscovered(System.String)) Event fired {"Name":"NarratorsDiscovered","Narrators":"full cast"}
 {}2022-03-30 09:52:48.318 -05:00 [DBG] (at FileLiberator.AudioDecodable.OnCoverImageDiscovered(System.Byte[])) Event fired {"Name":"CoverImageDiscovered","CoverImageBytes":58481}
 {}2022-03-30 09:52:48.319 -05:00 [INF] (at Dinah.Core.StepRunner.BaseStep.logEnd(System.Boolean, System.TimeSpan, System.Exception)) End step 'Step 1: Get Aaxc Metadata'. Success. Completed in 00:00:01
 {}2022-03-30 09:52:48.320 -05:00 [INF] (at Dinah.Core.StepRunner.BaseStep.logBegin()) Begin step 'Step 2: Download Decrypted Audiobook'
 {}2022-03-30 09:52:48.435 -05:00 [DBG] (at FileManager.FileUtility+<>c__DisplayClass32_0.<SaferDelete>b__0()) No file to delete: {"source":"C:\\Libation.6.7.4\\LibationFiles\\DecryptInProgress\\Impact Winter [B09PSLLWFG].m4b"}
 {}2022-03-30 09:53:33.203 -05:00 [INF] (at FileLiberator.Streamable.OnFileCreated(System.String, System.String)) File created {"Name":"FileCreated","id":"B09PSLLWFG","path":"C:\\Libation.6.7.4\\LibationFiles\\DecryptInProgress\\Impact Winter [B09PSLLWFG].m4b"}
 {}2022-03-30 09:53:33.216 -05:00 [INF] (at Dinah.Core.StepRunner.BaseStep.logEnd(System.Boolean, System.TimeSpan, System.Exception)) End step 'Step 2: Download Decrypted Audiobook'. Success. Completed in 00:00:44
 {}2022-03-30 09:53:33.216 -05:00 [INF] (at Dinah.Core.StepRunner.BaseStep.logBegin()) Begin step 'Step 3: Create Cue'
 {}2022-03-30 09:53:33.220 -05:00 [INF] (at FileLiberator.Streamable.OnFileCreated(System.String, System.String)) File created {"Name":"FileCreated","id":"B09PSLLWFG","path":"C:\\Libation.6.7.4\\LibationFiles\\DecryptInProgress\\Impact Winter [B09PSLLWFG].cue"}
 {}2022-03-30 09:53:33.230 -05:00 [INF] (at Dinah.Core.StepRunner.BaseStep.logEnd(System.Boolean, System.TimeSpan, System.Exception)) End step 'Step 3: Create Cue'. Success. Completed in 00:00:00
 {}2022-03-30 09:53:33.231 -05:00 [INF] (at Dinah.Core.StepRunner.BaseStep.logBegin()) Begin step 'Step 4: Cleanup'
 {}2022-03-30 09:53:33.232 -05:00 [DBG] (at FileManager.FileUtility+<>c__DisplayClass32_0.<SaferDelete>b__0()) Attempt to delete file: {"source":"C:\\Libation.6.7.4\\LibationFiles\\DecryptInProgress\\Impact Winter [B09PSLLWFG].json"}
 {}2022-03-30 09:53:33.235 -05:00 [INF] (at FileManager.FileUtility+<>c__DisplayClass32_0.<SaferDelete>b__0()) File successfully deleted: {"source":"C:\\Libation.6.7.4\\LibationFiles\\DecryptInProgress\\Impact Winter [B09PSLLWFG].json"}
 {}2022-03-30 09:53:33.236 -05:00 [DBG] (at FileManager.FileUtility+<>c__DisplayClass32_0.<SaferDelete>b__0()) Attempt to delete file: {"source":"C:\\Libation.6.7.4\\LibationFiles\\DecryptInProgress\\Impact Winter [B09PSLLWFG].tmp"}
 {}2022-03-30 09:53:33.262 -05:00 [INF] (at FileManager.FileUtility+<>c__DisplayClass32_0.<SaferDelete>b__0()) File successfully deleted: {"source":"C:\\Libation.6.7.4\\LibationFiles\\DecryptInProgress\\Impact Winter [B09PSLLWFG].tmp"}
 {}2022-03-30 09:53:33.263 -05:00 [INF] (at Dinah.Core.StepRunner.BaseStep.logEnd(System.Boolean, System.TimeSpan, System.Exception)) End step 'Step 4: Cleanup'. Success. Completed in 00:00:00
 {}2022-03-30 09:53:33.264 -05:00 [INF] (at Dinah.Core.StepRunner.BaseStep.logEnd(System.Boolean, System.TimeSpan, System.Exception)) End step 'Download and Convert Aaxc To M4b'. Success. Completed in 00:00:46
 {}2022-03-30 09:53:33.264 -05:00 [DBG] (at FileLiberator.Streamable.OnStreamingCompleted(System.String)) Event fired {"Name":"StreamingCompleted","Message":"Completed downloading and decrypting Impact Winter"}
 {}2022-03-30 09:53:33.351 -05:00 [DBG] (at FileManager.FileUtility+<>c__DisplayClass32_0.<SaferDelete>b__0()) No file to delete: {"source":"P:\\audible\\Travis Beacham\\Impact Winter [B09PSLLWFG]\\Impact Winter [B09PSLLWFG].m4b"}
 {}2022-03-30 09:53:33.357 -05:00 [DBG] (at FileManager.FileUtility+<>c__DisplayClass33_0.<SaferMove>b__0()) Attempt to create directory: {"dir":"P:\\audible\\Travis Beacham\\Impact Winter [B09PSLLWFG]"}
 {}2022-03-30 09:53:33.361 -05:00 [DBG] (at FileManager.FileUtility+<>c__DisplayClass33_0.<SaferMove>b__0()) Attempt to move file: {"source":"C:\\Libation.6.7.4\\LibationFiles\\DecryptInProgress\\Impact Winter [B09PSLLWFG].m4b","destination":"P:\\audible\\Travis Beacham\\Impact Winter [B09PSLLWFG]\\Impact Winter [B09PSLLWFG].m4b"}
 {}
rmcrackan commented 2 years ago

Well that's a kick in the teeth. It's crashing on the act of logging an error. Can you email me your Settings.json file? It's in the same folder as your log file.

pixil98 commented 2 years ago

Sent

rmcrackan commented 2 years ago

Thanks. I was worried about the log's settings but it looks perfect.

By the way, I assume you're on Win 10+ 64 bit?

Next thing to try:

I made a debug build for you.

Hopefully we'll learn something. If it still mysteriously vanishes, I have one more idea to try with my next debug build. After that, barring a lightbulb moment, I'm out of ideas.

pixil98 commented 2 years ago

Still crashing with the same symptoms:

2022-03-31 10:00:28.061 -05:00 [INF] (at AppScaffolding.LibationScaffolding.logStartupState(LibationFileManager.Configuration)) 

 {}2022-03-31 10:00:28.112 -05:00 [INF] (at AppScaffolding.LibationScaffolding.logStartupState(LibationFileManager.Configuration)) Begin. {"AppName":"Libation","Version":"6.7.4.1","Mode":"Debug","LogLevel_Verbose_Enabled":false,"LogLevel_Debug_Enabled":true,"LogLevel_Information_Enabled":true,"LogLevel_Warning_Enabled":true,"LogLevel_Error_Enabled":true,"LogLevel_Fatal_Enabled":true,"LibationFiles":"C:\\Users\\aaron\\Libation","BooksDirectory":"P:\\audible","InProgress":".\\LibationFiles","DownloadsInProgressDirectory":"C:\\LibationDebug\\LibationFiles\\DownloadsInProgress","DownloadsInProgressFiles":0,"DecryptInProgressDirectory":"C:\\LibationDebug\\LibationFiles\\DecryptInProgress","DecryptInProgressFiles":0}
 {}2022-03-31 10:00:31.098 -05:00 [DBG] (at LibationSearchEngine.SearchEngine.Search(System.String)) original search string: {"searchString":null}
 {}2022-03-31 10:00:31.101 -05:00 [DBG] (at LibationSearchEngine.SearchEngine.Search(System.String)) formatted search string: {"searchString":"*:*"}
 {}2022-03-31 10:00:31.233 -05:00 [DBG] (at LibationSearchEngine.SearchEngine.generalSearch(System.String)) query: {"queryString":"*:*"}
 {}2022-03-31 10:00:31.244 -05:00 [DBG] (at LibationSearchEngine.SearchEngine.Search(System.String)) Hit(s): {"count":772}
 {}2022-03-31 10:00:31.341 -05:00 [DBG] (at LibationSearchEngine.SearchEngine.Search(System.String)) original search string: {"searchString":""}
 {}2022-03-31 10:00:31.343 -05:00 [DBG] (at LibationSearchEngine.SearchEngine.Search(System.String)) formatted search string: {"searchString":"*:*"}
 {}2022-03-31 10:00:31.377 -05:00 [DBG] (at LibationSearchEngine.SearchEngine.generalSearch(System.String)) query: {"queryString":"*:*"}
 {}2022-03-31 10:00:31.379 -05:00 [DBG] (at LibationSearchEngine.SearchEngine.Search(System.String)) Hit(s): {"count":772}
 {}2022-03-31 10:00:32.646 -05:00 [INF] (at ApplicationServices.LibraryCommands.GetCounts()) Book counts. {"total":772,"booksFullyBackedUp":770,"booksDownloadedOnly":0,"booksNoProgress":2,"booksError":0}
 {}2022-03-31 10:00:32.661 -05:00 [INF] (at ApplicationServices.LibraryCommands.GetCounts()) PDF counts. {"total":31,"pdfsDownloaded":31,"pdfsNotDownloaded":0}
 {}2022-03-31 10:00:39.119 -05:00 [INF] (at LibationWinForms.BookLiberation.ProcessorAutomationController+<BackupSingleBookAsync>d__0.MoveNext()) Begin BackupSingleBookAsync {"AudibleProductId":"B09PSLLWFG"}
 {}2022-03-31 10:00:39.129 -05:00 [INF] (at FileLiberator.Processable+<ProcessSingleAsync>d__12.MoveNext()) Begin ProcessSingleAsync {"Title":"Impact Winter","AudibleProductId":"B09PSLLWFG","Locale":"us","Account":"[...]"}
 {}2022-03-31 10:00:39.134 -05:00 [DBG] (at FileLiberator.Processable.OnBegin(DataLayer.LibraryBook)) Event fired {"Name":"Begin","Book":["B09PSLLWFG","Impact Winter","us","[...]"]}
 {}2022-03-31 10:00:39.144 -05:00 [INF] (at LibationWinForms.BookLiberation.LogMe+<>c.<.ctor>b__9_0(System.Object, System.String)) Automated backup: Download & Decrypt Step, Begin: [B09PSLLWFG] Impact Winter
 {}2022-03-31 10:00:39.164 -05:00 [DBG] (at FileLiberator.Streamable.OnStreamingBegin(System.String)) Event fired {"Name":"StreamingBegin","Message":"Begin decrypting 3/29/2022 [B09PSLLWFG] Impact Winter"}
 {}2022-03-31 10:00:39.205 -05:00 [INF] (at AudibleUtilities.ApiExtended+<CreateAsync>d__9.MoveNext()) {"Username":"[...]","LocaleName":"us"}
 {}2022-03-31 10:00:40.014 -05:00 [DBG] (at FileManager.FileUtility+<>c__DisplayClass32_0.<SaferDelete>b__0()) No file to delete: {"source":"C:\\LibationDebug\\LibationFiles\\DecryptInProgress\\Impact Winter [B09PSLLWFG].m4b"}
 {}2022-03-31 10:00:40.021 -05:00 [INF] (at Dinah.Core.StepRunner.BaseStep.logBegin()) Begin step 'Download and Convert Aaxc To M4b'
 {}2022-03-31 10:00:40.022 -05:00 [INF] (at Dinah.Core.StepRunner.BaseStep.logBegin()) Begin step 'Step 1: Get Aaxc Metadata'
 {}2022-03-31 10:00:41.039 -05:00 [DBG] (at FileLiberator.AudioDecodable.OnTitleDiscovered(System.String)) Event fired {"Name":"TitleDiscovered","Title":"Impact Winter"}
 {}2022-03-31 10:00:41.041 -05:00 [DBG] (at FileLiberator.AudioDecodable.OnAuthorsDiscovered(System.String)) Event fired {"Name":"AuthorsDiscovered","Authors":"Travis Beacham"}
 {}2022-03-31 10:00:41.042 -05:00 [DBG] (at FileLiberator.AudioDecodable.OnNarratorsDiscovered(System.String)) Event fired {"Name":"NarratorsDiscovered","Narrators":"full cast"}
 {}2022-03-31 10:00:41.044 -05:00 [DBG] (at FileLiberator.AudioDecodable.OnCoverImageDiscovered(System.Byte[])) Event fired {"Name":"CoverImageDiscovered","CoverImageBytes":58481}
 {}2022-03-31 10:00:41.045 -05:00 [INF] (at Dinah.Core.StepRunner.BaseStep.logEnd(System.Boolean, System.TimeSpan, System.Exception)) End step 'Step 1: Get Aaxc Metadata'. Success. Completed in 00:00:01
 {}2022-03-31 10:00:41.045 -05:00 [INF] (at Dinah.Core.StepRunner.BaseStep.logBegin()) Begin step 'Step 2: Download Decrypted Audiobook'
 {}2022-03-31 10:00:41.049 -05:00 [DBG] (at FileManager.FileUtility+<>c__DisplayClass32_0.<SaferDelete>b__0()) No file to delete: {"source":"C:\\LibationDebug\\LibationFiles\\DecryptInProgress\\Impact Winter [B09PSLLWFG].m4b"}
 {}2022-03-31 10:01:25.802 -05:00 [INF] (at FileLiberator.Streamable.OnFileCreated(System.String, System.String)) File created {"Name":"FileCreated","id":"B09PSLLWFG","path":"C:\\LibationDebug\\LibationFiles\\DecryptInProgress\\Impact Winter [B09PSLLWFG].m4b"}
 {}2022-03-31 10:01:25.816 -05:00 [INF] (at Dinah.Core.StepRunner.BaseStep.logEnd(System.Boolean, System.TimeSpan, System.Exception)) End step 'Step 2: Download Decrypted Audiobook'. Success. Completed in 00:00:44
 {}2022-03-31 10:01:25.817 -05:00 [INF] (at Dinah.Core.StepRunner.BaseStep.logBegin()) Begin step 'Step 3: Create Cue'
 {}2022-03-31 10:01:25.821 -05:00 [INF] (at FileLiberator.Streamable.OnFileCreated(System.String, System.String)) File created {"Name":"FileCreated","id":"B09PSLLWFG","path":"C:\\LibationDebug\\LibationFiles\\DecryptInProgress\\Impact Winter [B09PSLLWFG].cue"}
 {}2022-03-31 10:01:25.832 -05:00 [INF] (at Dinah.Core.StepRunner.BaseStep.logEnd(System.Boolean, System.TimeSpan, System.Exception)) End step 'Step 3: Create Cue'. Success. Completed in 00:00:00
 {}2022-03-31 10:01:25.833 -05:00 [INF] (at Dinah.Core.StepRunner.BaseStep.logBegin()) Begin step 'Step 4: Cleanup'
 {}2022-03-31 10:01:25.834 -05:00 [DBG] (at FileManager.FileUtility+<>c__DisplayClass32_0.<SaferDelete>b__0()) Attempt to delete file: {"source":"C:\\LibationDebug\\LibationFiles\\DecryptInProgress\\Impact Winter [B09PSLLWFG].json"}
 {}2022-03-31 10:01:25.836 -05:00 [INF] (at FileManager.FileUtility+<>c__DisplayClass32_0.<SaferDelete>b__0()) File successfully deleted: {"source":"C:\\LibationDebug\\LibationFiles\\DecryptInProgress\\Impact Winter [B09PSLLWFG].json"}
 {}2022-03-31 10:01:25.837 -05:00 [DBG] (at FileManager.FileUtility+<>c__DisplayClass32_0.<SaferDelete>b__0()) Attempt to delete file: {"source":"C:\\LibationDebug\\LibationFiles\\DecryptInProgress\\Impact Winter [B09PSLLWFG].tmp"}
 {}2022-03-31 10:01:25.865 -05:00 [INF] (at FileManager.FileUtility+<>c__DisplayClass32_0.<SaferDelete>b__0()) File successfully deleted: {"source":"C:\\LibationDebug\\LibationFiles\\DecryptInProgress\\Impact Winter [B09PSLLWFG].tmp"}
 {}2022-03-31 10:01:25.866 -05:00 [INF] (at Dinah.Core.StepRunner.BaseStep.logEnd(System.Boolean, System.TimeSpan, System.Exception)) End step 'Step 4: Cleanup'. Success. Completed in 00:00:00
 {}2022-03-31 10:01:25.866 -05:00 [INF] (at Dinah.Core.StepRunner.BaseStep.logEnd(System.Boolean, System.TimeSpan, System.Exception)) End step 'Download and Convert Aaxc To M4b'. Success. Completed in 00:00:45
 {}2022-03-31 10:01:25.867 -05:00 [DBG] (at FileLiberator.Streamable.OnStreamingCompleted(System.String)) Event fired {"Name":"StreamingCompleted","Message":"Completed downloading and decrypting Impact Winter"}
 {}2022-03-31 10:01:25.976 -05:00 [DBG] (at FileManager.FileUtility+<>c__DisplayClass32_0.<SaferDelete>b__0()) No file to delete: {"source":"P:\\audible\\Travis Beacham\\Impact Winter [B09PSLLWFG]\\Impact Winter [B09PSLLWFG].m4b"}
 {}2022-03-31 10:01:25.992 -05:00 [DBG] (at FileManager.FileUtility+<>c__DisplayClass33_0.<SaferMove>b__0()) Attempt to create directory: {"dir":"P:\\audible\\Travis Beacham\\Impact Winter [B09PSLLWFG]"}
 {}2022-03-31 10:01:26.001 -05:00 [DBG] (at FileManager.FileUtility+<>c__DisplayClass33_0.<SaferMove>b__0()) Attempt to move file: {"source":"C:\\LibationDebug\\LibationFiles\\DecryptInProgress\\Impact Winter [B09PSLLWFG].m4b","destination":"P:\\audible\\Travis Beacham\\Impact Winter [B09PSLLWFG]\\Impact Winter [B09PSLLWFG].m4b"}
 {}
rmcrackan commented 2 years ago

Damn. Last idea. This debug version removes some advanced logging. Same instructions as before regarding appsettings.json. I also emailed you an edited settings file which is needed to ignore the advanced logging. Back up your current Settings.json and use the emailed one for testing.

pixil98 commented 2 years ago

Sadly it's still crashing:

2022-04-02 16:13:02.032 -05:00 [INF] (at AppScaffolding.LibationScaffolding.logStartupState(LibationFileManager.Configuration)) 

2022-04-02 16:13:02.078 -05:00 [INF] (at AppScaffolding.LibationScaffolding.logStartupState(LibationFileManager.Configuration)) Begin. {"AppName":"Libation","Version":"6.7.4.2","Mode":"Debug","LogLevel_Verbose_Enabled":false,"LogLevel_Debug_Enabled":true,"LogLevel_Information_Enabled":true,"LogLevel_Warning_Enabled":true,"LogLevel_Error_Enabled":true,"LogLevel_Fatal_Enabled":true,"LibationFiles":"C:\\Users\\aaron\\Libation","BooksDirectory":"P:\\audible","InProgress":".\\LibationFiles","DownloadsInProgressDirectory":"C:\\LibationDebug2\\LibationFiles\\DownloadsInProgress","DownloadsInProgressFiles":0,"DecryptInProgressDirectory":"C:\\LibationDebug2\\LibationFiles\\DecryptInProgress","DecryptInProgressFiles":0}
2022-04-02 16:13:04.893 -05:00 [DBG] (at LibationSearchEngine.SearchEngine.Search(System.String)) original search string: {"searchString":null}
2022-04-02 16:13:04.895 -05:00 [DBG] (at LibationSearchEngine.SearchEngine.Search(System.String)) formatted search string: {"searchString":"*:*"}
2022-04-02 16:13:05.019 -05:00 [DBG] (at LibationSearchEngine.SearchEngine.generalSearch(System.String)) query: {"queryString":"*:*"}
2022-04-02 16:13:05.029 -05:00 [DBG] (at LibationSearchEngine.SearchEngine.Search(System.String)) Hit(s): {"count":772}
2022-04-02 16:13:05.175 -05:00 [DBG] (at LibationSearchEngine.SearchEngine.Search(System.String)) original search string: {"searchString":""}
2022-04-02 16:13:05.177 -05:00 [DBG] (at LibationSearchEngine.SearchEngine.Search(System.String)) formatted search string: {"searchString":"*:*"}
2022-04-02 16:13:05.201 -05:00 [DBG] (at LibationSearchEngine.SearchEngine.generalSearch(System.String)) query: {"queryString":"*:*"}
2022-04-02 16:13:05.203 -05:00 [DBG] (at LibationSearchEngine.SearchEngine.Search(System.String)) Hit(s): {"count":772}
2022-04-02 16:13:05.815 -05:00 [INF] (at ApplicationServices.LibraryCommands.GetCounts()) Book counts. {"total":772,"booksFullyBackedUp":770,"booksDownloadedOnly":0,"booksNoProgress":2,"booksError":0}
2022-04-02 16:13:05.831 -05:00 [INF] (at ApplicationServices.LibraryCommands.GetCounts()) PDF counts. {"total":31,"pdfsDownloaded":31,"pdfsNotDownloaded":0}
2022-04-02 16:14:29.686 -05:00 [INF] (at AppScaffolding.LibationScaffolding.logStartupState(LibationFileManager.Configuration)) 

2022-04-02 16:14:29.732 -05:00 [INF] (at AppScaffolding.LibationScaffolding.logStartupState(LibationFileManager.Configuration)) Begin. {"AppName":"Libation","Version":"6.7.4.2","Mode":"Debug","LogLevel_Verbose_Enabled":false,"LogLevel_Debug_Enabled":true,"LogLevel_Information_Enabled":true,"LogLevel_Warning_Enabled":true,"LogLevel_Error_Enabled":true,"LogLevel_Fatal_Enabled":true,"LibationFiles":"C:\\Users\\aaron\\Libation","BooksDirectory":"P:\\audible","InProgress":".\\LibationFiles","DownloadsInProgressDirectory":"C:\\LibationDebug2\\LibationFiles\\DownloadsInProgress","DownloadsInProgressFiles":0,"DecryptInProgressDirectory":"C:\\LibationDebug2\\LibationFiles\\DecryptInProgress","DecryptInProgressFiles":0}
2022-04-02 16:14:32.424 -05:00 [DBG] (at LibationSearchEngine.SearchEngine.Search(System.String)) original search string: {"searchString":null}
2022-04-02 16:14:32.426 -05:00 [DBG] (at LibationSearchEngine.SearchEngine.Search(System.String)) formatted search string: {"searchString":"*:*"}
2022-04-02 16:14:32.551 -05:00 [DBG] (at LibationSearchEngine.SearchEngine.generalSearch(System.String)) query: {"queryString":"*:*"}
2022-04-02 16:14:32.561 -05:00 [DBG] (at LibationSearchEngine.SearchEngine.Search(System.String)) Hit(s): {"count":772}
2022-04-02 16:14:32.618 -05:00 [DBG] (at LibationSearchEngine.SearchEngine.Search(System.String)) original search string: {"searchString":""}
2022-04-02 16:14:32.620 -05:00 [DBG] (at LibationSearchEngine.SearchEngine.Search(System.String)) formatted search string: {"searchString":"*:*"}
2022-04-02 16:14:32.661 -05:00 [DBG] (at LibationSearchEngine.SearchEngine.generalSearch(System.String)) query: {"queryString":"*:*"}
2022-04-02 16:14:32.664 -05:00 [DBG] (at LibationSearchEngine.SearchEngine.Search(System.String)) Hit(s): {"count":772}
2022-04-02 16:14:33.693 -05:00 [INF] (at ApplicationServices.LibraryCommands.GetCounts()) Book counts. {"total":772,"booksFullyBackedUp":770,"booksDownloadedOnly":0,"booksNoProgress":2,"booksError":0}
2022-04-02 16:14:33.708 -05:00 [INF] (at ApplicationServices.LibraryCommands.GetCounts()) PDF counts. {"total":31,"pdfsDownloaded":31,"pdfsNotDownloaded":0}
2022-04-02 16:14:37.706 -05:00 [INF] (at LibationWinForms.BookLiberation.ProcessorAutomationController+<BackupSingleBookAsync>d__0.MoveNext()) Begin BackupSingleBookAsync {"AudibleProductId":"B09PSLLWFG"}
2022-04-02 16:14:37.716 -05:00 [INF] (at FileLiberator.Processable+<ProcessSingleAsync>d__12.MoveNext()) Begin ProcessSingleAsync {"Title":"Impact Winter","AudibleProductId":"B09PSLLWFG","Locale":"us","Account":"[...]"}
2022-04-02 16:14:37.721 -05:00 [DBG] (at FileLiberator.Processable.OnBegin(DataLayer.LibraryBook)) Event fired {"Name":"Begin","Book":["B09PSLLWFG","Impact Winter","us","[...]"]}
2022-04-02 16:14:37.784 -05:00 [INF] (at LibationWinForms.BookLiberation.LogMe+<>c.<.ctor>b__9_0(System.Object, System.String)) Automated backup: Download & Decrypt Step, Begin: [B09PSLLWFG] Impact Winter
2022-04-02 16:14:37.887 -05:00 [DBG] (at FileLiberator.Streamable.OnStreamingBegin(System.String)) Event fired {"Name":"StreamingBegin","Message":"Begin decrypting 3/29/2022 [B09PSLLWFG] Impact Winter"}
2022-04-02 16:14:37.916 -05:00 [INF] (at AudibleUtilities.ApiExtended+<CreateAsync>d__9.MoveNext()) {"Username":"[...]","LocaleName":"us"}
2022-04-02 16:14:39.680 -05:00 [DBG] (at FileManager.FileUtility+<>c__DisplayClass32_0.<SaferDelete>b__0()) No file to delete: {"source":"C:\\LibationDebug2\\LibationFiles\\DecryptInProgress\\Impact Winter [B09PSLLWFG].m4b"}
2022-04-02 16:14:39.686 -05:00 [INF] (at Dinah.Core.StepRunner.BaseStep.logBegin()) Begin step 'Download and Convert Aaxc To M4b'
2022-04-02 16:14:39.687 -05:00 [INF] (at Dinah.Core.StepRunner.BaseStep.logBegin()) Begin step 'Step 1: Get Aaxc Metadata'
2022-04-02 16:14:40.767 -05:00 [DBG] (at FileLiberator.AudioDecodable.OnTitleDiscovered(System.String)) Event fired {"Name":"TitleDiscovered","Title":"Impact Winter"}
2022-04-02 16:14:40.769 -05:00 [DBG] (at FileLiberator.AudioDecodable.OnAuthorsDiscovered(System.String)) Event fired {"Name":"AuthorsDiscovered","Authors":"Travis Beacham"}
2022-04-02 16:14:40.770 -05:00 [DBG] (at FileLiberator.AudioDecodable.OnNarratorsDiscovered(System.String)) Event fired {"Name":"NarratorsDiscovered","Narrators":"full cast"}
2022-04-02 16:14:40.772 -05:00 [DBG] (at FileLiberator.AudioDecodable.OnCoverImageDiscovered(System.Byte[])) Event fired {"Name":"CoverImageDiscovered","CoverImageBytes":58481}
2022-04-02 16:14:40.773 -05:00 [INF] (at Dinah.Core.StepRunner.BaseStep.logEnd(System.Boolean, System.TimeSpan, System.Exception)) End step 'Step 1: Get Aaxc Metadata'. Success. Completed in 00:00:01
2022-04-02 16:14:40.773 -05:00 [INF] (at Dinah.Core.StepRunner.BaseStep.logBegin()) Begin step 'Step 2: Download Decrypted Audiobook'
2022-04-02 16:14:40.875 -05:00 [DBG] (at FileManager.FileUtility+<>c__DisplayClass32_0.<SaferDelete>b__0()) No file to delete: {"source":"C:\\LibationDebug2\\LibationFiles\\DecryptInProgress\\Impact Winter [B09PSLLWFG].m4b"}
2022-04-02 16:15:25.847 -05:00 [INF] (at FileLiberator.Streamable.OnFileCreated(System.String, System.String)) File created {"Name":"FileCreated","id":"B09PSLLWFG","path":"C:\\LibationDebug2\\LibationFiles\\DecryptInProgress\\Impact Winter [B09PSLLWFG].m4b"}
2022-04-02 16:15:25.868 -05:00 [INF] (at Dinah.Core.StepRunner.BaseStep.logEnd(System.Boolean, System.TimeSpan, System.Exception)) End step 'Step 2: Download Decrypted Audiobook'. Success. Completed in 00:00:45
2022-04-02 16:15:25.870 -05:00 [INF] (at Dinah.Core.StepRunner.BaseStep.logBegin()) Begin step 'Step 3: Create Cue'
2022-04-02 16:15:25.873 -05:00 [INF] (at FileLiberator.Streamable.OnFileCreated(System.String, System.String)) File created {"Name":"FileCreated","id":"B09PSLLWFG","path":"C:\\LibationDebug2\\LibationFiles\\DecryptInProgress\\Impact Winter [B09PSLLWFG].cue"}
2022-04-02 16:15:25.889 -05:00 [INF] (at Dinah.Core.StepRunner.BaseStep.logEnd(System.Boolean, System.TimeSpan, System.Exception)) End step 'Step 3: Create Cue'. Success. Completed in 00:00:00
2022-04-02 16:15:25.889 -05:00 [INF] (at Dinah.Core.StepRunner.BaseStep.logBegin()) Begin step 'Step 4: Cleanup'
2022-04-02 16:15:25.890 -05:00 [DBG] (at FileManager.FileUtility+<>c__DisplayClass32_0.<SaferDelete>b__0()) Attempt to delete file: {"source":"C:\\LibationDebug2\\LibationFiles\\DecryptInProgress\\Impact Winter [B09PSLLWFG].json"}
2022-04-02 16:15:25.893 -05:00 [INF] (at FileManager.FileUtility+<>c__DisplayClass32_0.<SaferDelete>b__0()) File successfully deleted: {"source":"C:\\LibationDebug2\\LibationFiles\\DecryptInProgress\\Impact Winter [B09PSLLWFG].json"}
2022-04-02 16:15:25.897 -05:00 [DBG] (at FileManager.FileUtility+<>c__DisplayClass32_0.<SaferDelete>b__0()) Attempt to delete file: {"source":"C:\\LibationDebug2\\LibationFiles\\DecryptInProgress\\Impact Winter [B09PSLLWFG].tmp"}
2022-04-02 16:15:25.934 -05:00 [INF] (at FileManager.FileUtility+<>c__DisplayClass32_0.<SaferDelete>b__0()) File successfully deleted: {"source":"C:\\LibationDebug2\\LibationFiles\\DecryptInProgress\\Impact Winter [B09PSLLWFG].tmp"}
2022-04-02 16:15:25.935 -05:00 [INF] (at Dinah.Core.StepRunner.BaseStep.logEnd(System.Boolean, System.TimeSpan, System.Exception)) End step 'Step 4: Cleanup'. Success. Completed in 00:00:00
2022-04-02 16:15:25.935 -05:00 [INF] (at Dinah.Core.StepRunner.BaseStep.logEnd(System.Boolean, System.TimeSpan, System.Exception)) End step 'Download and Convert Aaxc To M4b'. Success. Completed in 00:00:46
2022-04-02 16:15:25.936 -05:00 [DBG] (at FileLiberator.Streamable.OnStreamingCompleted(System.String)) Event fired {"Name":"StreamingCompleted","Message":"Completed downloading and decrypting Impact Winter"}
2022-04-02 16:15:26.010 -05:00 [DBG] (at FileManager.FileUtility+<>c__DisplayClass32_0.<SaferDelete>b__0()) No file to delete: {"source":"P:\\audible\\Travis Beacham\\Impact Winter [B09PSLLWFG]\\Impact Winter [B09PSLLWFG].m4b"}
2022-04-02 16:15:26.015 -05:00 [DBG] (at FileManager.FileUtility+<>c__DisplayClass33_0.<SaferMove>b__0()) Attempt to create directory: {"dir":"P:\\audible\\Travis Beacham\\Impact Winter [B09PSLLWFG]"}
2022-04-02 16:15:26.020 -05:00 [DBG] (at FileManager.FileUtility+<>c__DisplayClass33_0.<SaferMove>b__0()) Attempt to move file: {"source":"C:\\LibationDebug2\\LibationFiles\\DecryptInProgress\\Impact Winter [B09PSLLWFG].m4b","destination":"P:\\audible\\Travis Beacham\\Impact Winter [B09PSLLWFG]\\Impact Winter [B09PSLLWFG].m4b"}
rmcrackan commented 2 years ago

Thank you for all of your efforts. I'm afraid I have no idea why this is crashing when it tries to log an error. I'm afraid I'm out of ideas. I've never seen this happen before.