Issue reading log when processing files

[BDaddyG]

Started receiving the following error when processing files:

Finished processing.

• ERRORED: Abigail Duhon - Rebound_t01.mkv
  Error: [TranscodeError: Could not confirm from log file that transcode succeeded.]
  File: Abigail Duhon - Rebound_t01.mkv

Summary: 1 file
Status: ER: 1
Processed: 108.00 MB of 108.00 total MB 2.81 MB/s
Time: Total 00h 00m 39s (Avg: 00h 00m 39s)

=> Finished with errors.

The only change I can think of is updating to the version of HandBrakeCLI to v1.2.0
I'm using the current version of batch-transcode-video
Command Line: batch-transcode-video --input "Source/" --output "Done/" --force 1 --diff

I looked at a successful transcode log file using HandBrakeCLI v1.1.2 and compared it to the failed v1.20 logs, but I didn't see anything.

Let me know if there is any further information I can provide.

Thanks

[CallumJHay]

I'm seeing the same thing.

I've done some tests with a few small MKV files set up in a test input directory, for transcoding to MP4 format in a separate output directory. If I watch the output directory as the batch process runs, all MP4's are created correctly but as the batch finishes, they are all deleted leaving only the logs.

It's as if there's some kind of final file cleanup going on, which is catching the output files by mistake.

[nwronski]

It sounds like the output of the underlying tools has changed in 1.2. Could you show me the output of the test you performed, but make sure you include the --debug flag @CallumJHay? batch-transcode-video --debug

[BDaddyG]

I did a quick test using --debug and here is the end section with the debug output (let me know if you want all the encoding output also)

Encode done!
HandBrake has exited.
stdio: Elapsed time: 00:00:54
stderr: /usr/local/rvm/gems/ruby-2.5.3/bin/transcode-video: output file exists: /home/redacted/Shared/Work/Done/Test.mkv

stderr: /usr/local/rvm/gems/ruby-2.5.3/bin/query-handbrake-log: not a HandBrake-generated .log file: /home/redacted/Shared/Work/Done/Test.mkv.log

Finished processing.

• ERRORED: Test.mkv
  Error: [TranscodeError: Could not confirm from log file that transcode succeeded.]
  File: Test.mkv

Summary: 1 file
Status: ER: 1
Processed: 22.00 MB of 22.00 total MB 0.39 MB/s
Time: Total 00h 00m 57s (Avg: 00h 00m 57s)

=> Finished with errors.

[CallumJHay]

I'm getting the same as BDaddyG has reported from --debug.

I've listed final part of output below, from completion of the last of a set of 5 small test MKV files. As you can see, system thinks .log file is not right, then after all processing finished ERRORs them all.

Full debug file here:
Debug.txt

MP4 output folder screenshots during processing, and after processing finished here:

Log file from the last of 5 MKV's processed here:
title_t09.mp4.log

Also, should have said in my first post this wrapper is a marvellous bit of work and potentially a really useful tool for me - can't thank you enough!

Encode done!
HandBrake has exited.
stdio: Elapsed time: 00:00:56
stderr: /usr/local/bin/transcode-video: output file exists: /mnt/f/Video Conversion Batch/MP4 Output/title_t09.mp4

stderr: /usr/local/bin/query-handbrake-log: not a HandBrake-generated .log file: /mnt/f/Video Conversion Batch/MP4 Output/title_t09.mp4.log

Finished processing.

• ERRORED: title_t05.mkv
  Error: [TranscodeError: Could not confirm from log file that transcode succeeded.]
  File: title_t05.mp4

• ERRORED: title_t06.mkv
  Error: [TranscodeError: Could not confirm from log file that transcode succeeded.]
  File: title_t06.mp4

• ERRORED: title_t07.mkv
  Error: [TranscodeError: Could not confirm from log file that transcode succeeded.]
  File: title_t07.mp4

• ERRORED: title_t08.mkv
  Error: [TranscodeError: Could not confirm from log file that transcode succeeded.]
  File: title_t08.mp4

• ERRORED: title_t09.mkv
  Error: [TranscodeError: Could not confirm from log file that transcode succeeded.]
  File: title_t09.mp4

Summary: 5 files
Status: ER: 5
Processed: 594.00 MB of 594.00 total MB 1.79 MB/s
Time: Total 00h 05m 32s (Avg: 00h 01m 06s)

=> Finished with errors.

[nwronski]

What do you get if you run the query-handbrake-log command against one of those log files? For example:

query-handbrake-log bitrate /home/redacted/Shared/Work/Done/Test.mkv.log

query-handbrake-log bitrate '/mnt/f/Video Conversion Batch/MP4 Output/title_t09.mp4.log'

The important bit from the debug output is this part, which is coming from the query-handbrake-log command that is run after each file encode is finished:

stderr: /usr/local/bin/query-handbrake-log: not a HandBrake-generated `.log` file: /mnt/f/Video Conversion Batch/MP4 Output/title_t09.mp4.log

If batch-transcode-video doesn't get a bitrate from that command, it marks the file as errored.

[nwronski]

Until we can figure out the root issue, I have added a --keep option to prevent the program from deleting files from the output directory, even when an error occurs. You can grab the new version with npm i -g batch-transcode-video@1.3.0. More information about the new option and why files are being deleted from the output folder over here at this comment.

[BDaddyG]

@nwronski

Here is the output you requested:

redacted@avconvert2:~/Shared/Work/Done$ query-handbrake-log bitrate Test.mkv.log
/usr/local/rvm/gems/ruby-2.5.3/bin/query-handbrake-log: not a HandBrake-generated .log file: /home/redacted/Shared/Work/Done/Test.mkv.log

The same only with the verbose flag:

redacted@avconvert2:~/Shared/Work/Done$ query-handbrake-log -v bitrate Test.mkv.log
query-handbrake-log 0.23.0
Copyright (c) 2013-2019 Don Melton
Processing: Test.mkv.log...
Reading: /home/redacted/Shared/Work/Done/Test.mkv.log...
/usr/local/rvm/gems/ruby-2.5.3/bin/query-handbrake-log: not a HandBrake-generated .log file: /home/redacted/Shared/Work/Done/Test.mkv.log

So the issue seems to be with query-handbrake-log. I've opened a ticket with Don's video_transcoding (lisamelton/video_transcoding#257) asking him to take a look at a failing log.

Thanks!

Edit: fixed URL link

[BDaddyG]

@nwronski

Don has confirmed that there is an apparent bug with Handbrake v1.20 on certain Linux platforms where extra lines are produced at the beginning of the HandBrake log which triggers a check he has in query-handbrake-log. These extra lines make query-handbrake-log think the log isn't valid.

Don will be releasing a patch for this soon (and a new version of video_transcoding this week).

Don did ask that I let you know the following:

... let @nwronski know that it's much safer and faster to check whether the string "Encode done!" exists as a single line in the ".log" file to verify that HandBrake succeeded. That's what I do with some of my own scripts.

Thanks for your scripts and your work on this issue!

[lisamelton]

@nwronski @BDaddyG The patch is done but you really shouldn't be using query-handbrake-log bitrate to test whether a transcode succeeded. That's because HandBrakeCLI will still spew the information that query-handbrake-log needs to the ".log" file when it fails or even if you interrupt it with a "^C" (control + C) key sequence. And I actually depend on that behavior to inspect partial transcodings. It's essential to testing.

So, I strongly recommend that you check whether the string "Encode done!" exists as a single line in the ".log" file to verify that HandBrake succeeded. Here's a fragment from one of my many scripts which does this very thing:

if [ ! -f "$log" ] || ! $(grep -q '^Encode done!$' "$log"); then
    die "transcoding failed: $input"
fi

Happy transcoding!

[JMoVS]

any news on this? Has this change been incorporated?

[nwronski]

the issue you were experiencing should be resolved in the latest release (v2.0.0), but please reopen this issue if the problem persists, thanks! the program is now more forgiving when determining if the transcode job finished successfully. taking the advice of @donmelton, it only checks the output for the text Encoding done! to decide if the job succeeded. also, if the program fails to query the bitrate from the log file, it is no longer treated as an error.

npm i -g batch-transcode-video@2