I have a conversion that I have been using for several years that renames recordings to be Plex compatible and then moves the recording to a folder based on the shows name.
Starting about 3 or 4 weeks ago, some file moves have randomly failed. Either a short time later or the next night, the move succeeds. This is resulting in duplicates of some shows.
I attached the main log and one example of a show that was duplicated. Shows that have displayed this behavior are: FBI International, Magnum, & Quantum Leap.
I have not been able to determine why this is happening.
Thanks for your assistance. mcebuddy.zip (66.8 KB)
Here are some examples from the log:
INFORMATION> 2023-03-01T02:16:02 MCEBuddy.Engine.Core --> Job for \\MEDIACENTER\Recorded TV\FBI- International_s02e14 He Who Speaks Dies_WCBSDT_2023_02_28_20_55_00.wtv completed
INFORMATION> 2023-03-01T02:16:02 --> Job for \\MEDIACENTER\Recorded TV\FBI- International_s02e14 He Who Speaks Dies_WCBSDT_2023_02_28_20_55_00.wtv has Error Moving converted file to destination failed using conversion task -> Move WTV Recorded TV and profile -> WTV Unprocessed
INFORMATION> 2023-03-01T02:16:03 --> Request to send eMail
2023-03-01T02:16:03 --> Server -> xxxxxxxxx
2023-03-01T02:16:03 --> Port -> 25
2023-03-01T02:16:03 --> SSL -> False
2023-03-01T02:16:03 --> Username -> xxxxxxxxx
2023-03-01T02:16:03 --> From -> xxxxxxxxx
2023-03-01T02:16:03 --> To -> xxxxxxxxx
2023-03-01T02:16:03 --> Subject -> MCEBuddy failed to converted a video
2023-03-01T02:16:03 --> Message -> Source Video -> \\MEDIACENTER\Recorded TV\FBI- International_s02e14 He Who Speaks Dies_WCBSDT_2023_02_28_20_55_00.wtv
Profile -> WTV Unprocessed
Conversion Task -> Move WTV Recorded TV
Error -> Moving converted file to destination failed
Failed At -> 2023-03-01T02:16:02
INFORMATION> 2023-02-27T02:35:33 MCEBuddy.Engine.Core --> Job for \\MEDIACENTER\Recorded TV2\Magnum P.I._s05e03 Number One With a Bullet_WNBCDT_2023_02_26_20_55_00.wtv completed
INFORMATION> 2023-02-27T02:35:33 --> Job for \\MEDIACENTER\Recorded TV2\Magnum P.I._s05e03 Number One With a Bullet_WNBCDT_2023_02_26_20_55_00.wtv has Error Moving converted file to destination failed using conversion task -> Move WTV Recorded TV and profile -> WTV Unprocessed
INFORMATION> 2023-02-27T02:35:33 --> Request to send eMail
2023-02-27T02:35:33 --> Server -> xxxxxxxxx
2023-02-27T02:35:33 --> Port -> 25
2023-02-27T02:35:33 --> SSL -> False
2023-02-27T02:35:33 --> Username -> xxxxxxxxx
2023-02-27T02:35:33 --> From -> xxxxxxxxx
2023-02-27T02:35:33 --> To -> xxxxxxxxx
2023-02-27T02:35:33 --> Subject -> MCEBuddy failed to converted a video
2023-02-27T02:35:33 --> Message -> Source Video -> \\MEDIACENTER\Recorded TV2\Magnum P.I._s05e03 Number One With a Bullet_WNBCDT_2023_02_26_20_55_00.wtv
Profile -> WTV Unprocessed
INFORMATION> 2023-02-27T03:39:46 MCEBuddy.Engine.Core --> Job for \\MEDIACENTER\Recorded TV2\The Equalizer_s03e09 Second Chance_WCBSDT_2023_02_26_19_00_00.wtv completed
INFORMATION> 2023-02-27T03:39:46 --> Job for \\MEDIACENTER\Recorded TV2\The Equalizer_s03e09 Second Chance_WCBSDT_2023_02_26_19_00_00.wtv has Error Moving converted file to destination failed using conversion task -> Move WTV Recorded TV and profile -> WTV Unprocessed
INFORMATION> 2023-02-27T03:39:46 --> Request to send eMail
2023-02-27T03:39:46 --> Server -> xxxxxxxxx
2023-02-27T03:39:46 --> Port -> 25
2023-02-27T03:39:46 --> SSL -> False
2023-02-27T03:39:46 --> Username -> xxxxxxxxx
2023-02-27T03:39:46 --> From -> xxxxxxxxx
2023-02-27T03:39:46 --> To -> xxxxxxxxx
2023-02-27T03:39:46 --> Subject -> MCEBuddy failed to converted a video
2023-02-27T03:39:46 --> Message -> Source Video -> \\MEDIACENTER\Recorded TV2\The Equalizer_s03e09 Second Chance_WCBSDT_2023_02_26_19_00_00.wtv
Profile -> WTV Unprocessed
Conversion Task -> Move WTV Recorded TV
Error -> Moving converted file to destination failed
Failed At -> 2023-02-27T03:39:46
The log file you attached is showing the conversion was successful and it was able to move the file to the destination NAS folder
INFORMATION> 2023-03-01T02:56:13 --> Job for \\MEDIACENTER\Recorded TV\La Brea_s02e14 The Journey, Part 2_WNBCDT_2023_02_28_22_00_04.wtv converted successfully to \\MEDIACENTER\Recorded TV\La Brea\La Brea - S02E14_2023_02_28.wtv using conversion task -> Move WTV Recorded TV and profile -> WTV Unprocessed
INFORMATION> 2023-03-01T02:56:13 --> Request to send eMail
2023-03-01T02:56:13 --> Server -> xxxxxxxxx
2023-03-01T02:56:13 --> Port -> 25
2023-03-01T02:56:13 --> SSL -> False
2023-03-01T02:56:13 --> Username -> xxxxxxxxx
2023-03-01T02:56:13 --> From -> xxxxxxxxx
2023-03-01T02:56:13 --> To -> xxxxxxxxx
2023-03-01T02:56:13 --> Subject -> MCEBuddy successfully converted a video
2023-03-01T02:56:13 --> Message -> Source Video -> \\MEDIACENTER\Recorded TV\La Brea_s02e14 The Journey, Part 2_WNBCDT_2023_02_28_22_00_04.wtv
Converted Video -> \\MEDIACENTER\Recorded TV\La Brea\La Brea - S02E14_2023_02_28.wtv
Profile -> WTV Unprocessed
Conversion Task -> Move WTV Recorded TV
Converted At -> 2023-03-01T02:56:13
Time taken to convert (hh:mm) -> 00:14
2023-03-01T02:56:13 MCEBuddy.Engine.Core --> No conversions running, allowing system sleep
2023-03-01T02:56:13 MCEBuddy.Engine.ConversionJob --> Starting Conversion Thread
INFORMATION> 2023-03-01T02:56:13 MCEBuddy.Engine.ConversionJob --> Creating log file : C:\Program Files\MCEBuddy2x\log\FBI International - S02E14_2023_02_28.wtv-Move WTV Recorded TV-1900-01-01T00-00-00.log
INFORMATION> 2023-03-01T02:56:13 MCEBuddy.Engine.Core --> Job for \\MEDIACENTER\Recorded TV\FBI International\FBI International - S02E14_2023_02_28.wtv started using conversion task -> Move WTV Recorded TV and profile -> WTV Unprocessed
2023-03-01T02:56:13 MCEBuddy.Engine.Core --> Temp working path is C:\Program Files\MCEBuddy2x\working0
2023-03-01T02:56:13 MCEBuddy.Engine.Core --> Starting new conversions, preventing system sleep
INFORMATION> 2023-03-01T02:56:14 --> Successfully send eMail
WARNING> 2023-03-01T02:56:25 MCEBuddy.Engine.QueueManager --> Monitor task E Drive Recorded TV : Unable to queue file for conversion - file inaccessible/locked by another process \\MEDIACENTER\Recorded TV\La Brea_s02e14 The Journey, Part 2_WNBCDT_2023_02_28_22_00_04.wtv
2023-03-01T02:56:26 MCEBuddy.Engine.QueueManager --> Monitor task E Drive Recorded TV : File \\MEDIACENTER\Recorded TV\FBI Most Wanted\FBI Most Wanted - S04E14_2023_02_28.wtv already converted with status OutputFromConversion
2023-03-01T02:56:26 MCEBuddy.Engine.QueueManager --> Monitor task E Drive Recorded TV : File \\MEDIACENTER\Recorded TV\La Brea\La Brea - S02E14_2023_02_28.wtv already converted with status OutputFromConversion
INFORMATION> 2023-03-01T03:10:28 MCEBuddy.Engine.QueueManager --> No accessible files founds in location \\MEDIACENTER\Recorded TV5 for monitor task I Drive Recorded TV5
INFORMATION> 2023-03-01T03:11:53 MCEBuddy.Engine.Core --> Job for \\MEDIACENTER\Recorded TV\FBI International\FBI International - S02E14_2023_02_28.wtv completed
2023-03-01T03:11:53 MCEBuddy.Engine.Core --> Deleting original file \\MEDIACENTER\Recorded TV\FBI International\FBI International - S02E14_2023_02_28.wtv
2023-03-01T03:11:53 MCEBuddy.Engine.QueueManager --> Deleting directory \\MEDIACENTER\Recorded TV\FBI International
ERROR> 2023-03-01T03:11:53 MCEBuddy.Engine.QueueManager --> Unable to read parent directory contents \\MEDIACENTER\Recorded TV\FBI International
System.IO.IOException: The directory is not empty.
at System.IO.__Error.WinIOError(Int32 errorCode, String maybeFullPath)
at System.IO.Directory.DeleteHelper(String fullPath, String userPath, Boolean recursive, Boolean throwOnTopLevelDirectoryNotFound, WIN32_FIND_DATA& data)
at System.IO.Directory.Delete(String fullPath, String userPath, Boolean recursive, Boolean checkHost)
at MCEBuddy.Engine.QueueManager.DeleteParentDirectoryChainIfEmpty(String filePath, String uptoParentFolder)
INFORMATION> 2023-03-01T03:11:53 --> Job for \\MEDIACENTER\Recorded TV\FBI International\FBI International - S02E14_2023_02_28.wtv converted successfully to \\MEDIACENTER\Recorded TV\FBI International\FBI International\FBI International - S02E14_2023_02_28.wtv using conversion task -> Move WTV Recorded TV and profile -> WTV Unprocessed
INFORMATION> 2023-03-01T03:11:53 --> Request to send eMail
2023-03-01T03:11:53 --> Server -> xxxxxxxxx
2023-03-01T03:11:53 --> Port -> 25
2023-03-01T03:11:53 --> SSL -> False
2023-03-01T03:11:53 --> Username -> xxxxxxxxx
2023-03-01T03:11:53 --> From -> xxxxxxxxx
2023-03-01T03:11:53 --> To -> xxxxxxxxx
2023-03-01T03:11:53 --> Subject -> MCEBuddy successfully converted a video
2023-03-01T03:11:53 --> Message -> Source Video -> \\MEDIACENTER\Recorded TV\FBI International\FBI International - S02E14_2023_02_28.wtv
Converted Video -> \\MEDIACENTER\Recorded TV\FBI International\FBI International\FBI International - S02E14_2023_02_28.wtv
Profile -> WTV Unprocessed
Conversion Task -> Move WTV Recorded TV
Converted At -> 2023-03-01T03:11:53
Time taken to convert (hh:mm) -> 00:15
2023-03-01T03:11:53 MCEBuddy.Engine.Core --> No conversions running, allowing system sleep
INFORMATION> 2023-03-01T03:11:55 --> Successfully send eMail
INFORMATION> 2023-03-01T03:15:26 MCEBuddy.Engine.QueueManager --> No accessible files founds in location \\MEDIACENTER\Recorded TV-C for monitor task C Drive Recorded TV-C
2023-03-01T03:15:31 MCEBuddy.Engine.QueueManager --> Monitor task E Drive Recorded TV : File \\MEDIACENTER\Recorded TV\FBI International\FBI International\FBI International - S02E14_2023_02_28.wtv already converted with status OutputFromConversion
However I do see other errors related to reading and deleting directories on the NAS. The files are locked or the NAS is denying access to these files/directories.
If you’re seeing issues with a NAS it’s normally a NAS issue. These can be cause of network issues, sharing issues with other computers, internal NAS issues (like date/time being incorrect which can cause access denials) etc. Was there an update to your NAS firmware recently? See this post also
In the case you mention that the file was moved, it was done the next day after the processing.
I had the issue with The Equalizer last night. The file could not be moved and I received an email indicating the failure.
However, I may have found the issue, I won’t know for a few days.
I have a time restriction for the allotted time that MCEBuddy can run. There were about 6 shows to process last night & it may have exceed the time limitation. I increased the time frame today, so let me see what happens over the next few days.
I had thought increasing the processing time for mcebuddy to run was going to solve all of my issues. But I am still experiencing random move failures.
There has been no changes in firmware or anything else on the nas unit. I went in to mcebuddy and confirmed access through the setup link.
A couple of times since, I received a fail move email. The last time was last night for one of my wife’s shows. This was a movie and all that should happen is to move the file to a subfolder of Movies, using the name of the movie as file name, along with year, and rename the movie to add the year. No commercial removal is done.
When I checked the nas unit, I found the movie in the originally recorded position, and the movie had been moved to the movies folder. However, the file folder organization was not correct.
I had:
Movies - A Winning Team (2023) - Movies - A Winning Team (2023) - the movie file with the correct show name.
For some reason it duplicated the Movies - A Winning Team (2023) folder. I normally only see this when the move operation happens twice.
There are issues with your NAS / network connectivity. Windows is unable to consistently read the folders
ERROR> 2023-03-19T01:32:10 MCEBuddy.Engine.QueueManager → Unable to read parent directory contents \MEDIACENTER\Recorded TV2\Movies\A Winning Team (2023)
System.IO.IOException: The directory is not empty.
at System.IO.__Error.WinIOError(Int32 errorCode, String maybeFullPath)
at System.IO.Directory.DeleteHelper(String fullPath, String userPath, Boolean recursive, Boolean throwOnTopLevelDirectoryNotFound, WIN32_FIND_DATA& data)
at System.IO.Directory.Delete(String fullPath, String userPath, Boolean recursive, Boolean checkHost)
at MCEBuddy.Engine.QueueManager.DeleteParentDirectoryChainIfEmpty(String filePath, String uptoParentFolder)
INFORMATION> 2023-03-19T00:58:18 MCEBuddy.Engine.ConversionJob → Moving converted file C:\Program Files\MCEBuddy2x\working0\A Winning Team (2023).wtv to \MEDIACENTER\Recorded TV2\Movies\A Winning Team (2023)\A Winning Team (2023).wtv
ERROR> → Unable to move file C:\Program Files\MCEBuddy2x\working0\A Winning Team (2023).wtv to \MEDIACENTER\Recorded TV2
Error :System.IO.IOException: An unexpected network error occurred.
at System.IO.__Error.WinIOError(Int32 errorCode, String maybeFullPath)
at System.IO.File.InternalMove(String sourceFileName, String destFileName, Boolean checkHost)
at MCEBuddy.Util.FileIO.MoveAndInheritPermissions(String source, String destination, Boolean overwriteDestination)
at MCEBuddy.Engine.ConversionJob.MoveConvertedFile(String subDestinationPath, Log jobLog)
ERROR> 2023-03-19T01:04:04 MCEBuddy.Engine.ConversionJob → Moving converted file to destination failed
This would explain all your intermittent issues including duplications because it looks like the file was actually transferred but your NAS returns an error to the windows machine so MCEBuddy it think it wasn’t successful and doesn’t delete the original file. Because you’ve setup MCEBuddy to process and replace the files in the original folder, now it will see 2 separate files for processing, the original file it and the “failed” converted file (since it’s internal record shows it wasn’t successful it won’t ignore the converted file) and now you’ll end up with 2 reprocessed files.
All these issues are related to your network issues and the fact that you’re using the same folder for the original and destination. If they were separate folders the issue may be less impactful with such network issues (as in the original file will eventually be deleted as they’re going to different folders).