Bug Report: libx265_encoder and video_remuxer

[CptChaz]

I apologize for the length of this post, just wanted to be thorough:

ISSUE

file failures with video_remuxer plugin enabled, that have source files already in desired codec and format.

DESCRIPTION

Initially I noticed the libx265_encoder plugin did not remux containers if the source file was already in the hevc codec. For example, assume .mp4 is the desired output: if the source is x264.mkv, the plugin will output x265.mp4. However, if source is x265.mkv, libx265_encoder will skip and the source file remained x265.mkv as evidenced by this log for "Black Widow.txt"
Black_Widow.txt (Note there are no errors in this log, the source file was x265, so it remained x265.mkv) Suspecting this was perhaps by design, I additionally enabled the video_remuxer plugin to change container output of existing x265 files that were not in mp4 format.

After enabling both libx265_encoder and video_remuxer plugin, the remuxer worked perfectly to catch x265.mkv containers. The rub here, is that source files that are already in the desired codec and format are now failing. for example, x265.mp4 (which is having other plugins ran against it) is failing. you can see from a screenshot of the Completed Tasks

that all existing x265.mp4's are failing. I'm unable to show any specific ffmpeg file log (which seems to be another issue) for the specific file failures
.

Just to show that these files are in fact x265.mp4, here is an ffprobe of a recent file failure for "Kung Fu Panda (2011)"
ffprobe_x265mp4.txt

Finally, here is the unmanic.log file corroborating the issue on line 7925 for this specific file (as well as others).
unmanic.log

SOLUTION

Seems like the easiest short term fix would be to have the libx265_encoder (and the other encoders) remux the video containers if a different output format is specified even though they already have desired codec. (This would also reduce the additional need to have the video_remuxer plugin enabled.) However, I think the issue actually does lie somewhere with the video_remuxer plugin. Happy to provide any additional information I may have missed.

[CptChaz]

Just realizing from the screenshot of completed tasks that the failures are actually duplicates!

kung fu panda secrets of the masters (2011) Bluray-720p.mkv completed successfully, then a few tasks later is shown as kung fu panda secrets of the masters (2011) Bluray-720p.mp4 and fails.

[Josh5]

The video encoders will not remux unless they find a file to transcode video for.
Their primary function is video transcodeing, the remux is just an aside...

For remuxing, i would recommend the remux plugin as that is the only plugin which will add files from a library scan if it is not the correct container (which is what you have done).

I think I understand the issue and what is going on here. I can create a fix for it... But this may also be a PICNIC...

Are you re-adding the files from the completed task list? Or are you running a library scan?

[Josh5]

I can reproduce this if I process a file (so that it is now in the format I want eg h264 mkv). Then go to the completed tasks and select the successfully completed file, then select "add selected to pending task list" from the options menu.
I get no command logs and the same error you have:

2021-09-16T17:18:31:INFO:Unmanic.Worker-W0 - [FORMATTED] - Successfully converted file '/library/tmp/haruhi-9.mkv'
2021-09-16T17:18:31:DEBUG:Unmanic.Worker-W0 - [FORMATTED] - Final cache file is the same path as the original source.
2021-09-16T17:18:31:INFO:Unmanic.Worker-W0 - [FORMATTED] - Moving final cache file from '/library/tmp/haruhi-9.mkv' to '/tmp/unmanic/unmanic_file_conversion-1631769509.434256/haruhi-9-1631769511.9327724.mkv'
2021-09-16T17:18:31:ERROR:Unmanic.Worker-W0 - [FORMATTED] - Exception in final move operation of file /library/tmp/haruhi-9.mkv to /tmp/unmanic/unmanic_file_conversion-1631769509.434256/haruhi-9-1631769511.9327724.mkv: - [Errno 2] No such file or directory: '/tmp/unmanic/unmanic_file_conversion-1631769509.434256/haruhi-9-1631769511.9327724.mkv'
Traceback (most recent call last):
  File "/usr/lib/python3.8/shutil.py", line 791, in move
    os.rename(src, real_dst)
FileNotFoundError: [Errno 2] No such file or directory: '/library/tmp/haruhi-9.mkv' -> '/tmp/unmanic/unmanic_file_conversion-1631769509.434256/haruhi-9-1631769511.9327724.mkv'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/josh5/dev/mystuff/unmanic/unmanic/libs/workers.py", line 451, in __exec_worker_runners_on_set_task
    shutil.move(current_file_out, task_cache_path)
  File "/usr/lib/python3.8/shutil.py", line 811, in move
    copy_function(src, real_dst)
  File "/usr/lib/python3.8/shutil.py", line 435, in copy2
    copyfile(src, dst, follow_symlinks=follow_symlinks)
  File "/usr/lib/python3.8/shutil.py", line 264, in copyfile
    with open(src, 'rb') as fsrc, open(dst, 'wb') as fdst:
FileNotFoundError: [Errno 2] No such file or directory: '/tmp/unmanic/unmanic_file_conversion-1631769509.434256/haruhi-9-1631769511.9327724.mkv'

[Josh5]

basically, the plugins had nothing to do to modify this file so nothing was done
therefore there were no cache files...
therefore Unmanic tried to move the original file to a cache file...

I need to change Unmanic so that if the original file is the final cache file... just end successfully (dont fail as that means something went wrong) and log a single error to the command log that says "No plugin runners were run against this file"

[CptChaz]

No, i'm not manually re-adding them - i didn't even realize they were duplicates until after i posted. Have library scan set to once per day. Also had not seen any errors like this before enabling the remux plugin.

[Josh5]

What plugins do you have enabled?
I cannot reproduce this without manually re-adding a file from the completed task list.

I have enabled this:

[Josh5]

Are you able to reproduce this with debugging enabled?

[Josh5]

poke

[CptChaz]

Sorry i dropped the ball on this. was in the midst of a bunch of traveling and just now getting back around to it.

i am still seeing the behavior though. i just enabled debugging, so i'll attempt to reproduce and report back posthaste.

[CptChaz]

UnmanicLogs.zip

I'm still able to reproduce this, as seen in this screenshot here. debugging was enabled before 10/13. Note date and time in the screenshot for log reference. The twice-processed episode of New Amsterdam is shown in the debugging log. The other twice-processed files highlighted in blue were in the log for 10/12 before debugging.

My desired container output is .mp4. It looks like source files already in that format, are only processed once. If the source is .mkv (or presumable some other format), it's processed, but then unmanic (or the respective plugin) isn't recognizing the new filename appended with .mp4, so it processes it again. Salt in this wound is, these videos get trimmed twice haha!

Here's a shot of the enabled plugins.

Also if needed, here are the ffmpeg logs for both of the New Amsterdam files.
FFMPEG_New Amsterdam (2018) - s04e04.mkv.txt
FFMPEG_New Amsterdam (2018) - s04e04.mp4.txt

These logs and screenshots are all running on Staging, Version - 0.1.1+b11fd46

[CptChaz]

I've disabled the Video Trim plugin for now. As you can see in this screen shot, this particular file was processed repeatedly (29 times). It had gotten to the point where the file was only down to 2 mins long. ffmpeg log for each file was showing video trim and audio normaliser plugins ran each time.

I thought maybe it would be helpful to post the contents of the .unmanic file here for that particular media file, and realized that it doesn't have one.

This prompted me to investigate another file that has been processed repeatedly. ffmpeg logs showing each time that only the video trim plugin ran

The folder for this media did contain a file_info and .unmanic file. file_info appeared normal, but here's the .unmanic file that appears to be out of sorts, like the video_trim plugin isn't appending it correctly or something