VidCoder icon indicating copy to clipboard operation
VidCoder copied to clipboard

VidCoder Encodes are continually failing whereas Encodes using native Handbrake succeed

Open fbagnato opened this issue 1 year ago • 15 comments

Problem Description

I cannot get VidCoder to successfully encode ISO video files.

The encode always fails, usually within minutes of it starting.

I can encode the same file with the same settings in Handbrake without any problems.

What version of VidCoder are you running?

10.14 VelopackInstaller

Encode Log

VC [19:08:43] VidCoder 10.14
VC [19:08:43] Starting job 1/1
VC [19:08:43]   Source path: C:\Users\Flavio\Desktop\The Magnificent Seven.iso
VC [19:08:43]   Destination path: C:\Users\Flavio\Desktop\The Magnificent Seven.mp4
VC [19:08:43]   Title: 1
VC [19:08:43]   Range: All
VC [19:08:43]   Preset: HQ 2160p60 4K AV1 Surround
VC [19:08:43]   Picker: 
VC [19:08:47] Worker ready: Pipe 'VidCoderWorker.8a8ebb7f-355c-4a6f-b7fd-30073918fde9' is open
VC [19:08:47] Connecting to process 13656 on pipe VidCoderWorker.8a8ebb7f-355c-4a6f-b7fd-30073918fde9
HB [19:10:51] hb_init: starting libhb thread
[19:10:51] CPU: Intel(R) Core(TM) i5-3317U CPU @ 1.70GHz
[19:10:51]  - Intel microarchitecture Ivy Bridge
[19:10:51]  - logical processor count: 4
[19:10:51] Intel Quick Sync Video support: no
[19:10:51] hb_scan: path=C:\Users\Flavio\Desktop\The Magnificent Seven.iso, title_index=1
HB src/libbluray/disc/disc.c:437: error opening file BDMV\index.bdmv
src/libbluray/disc/disc.c:437: error opening file BDMV\BACKUP\index.bdmv
[19:10:52] bd: not a bd - trying as a stream/file instead
[19:10:59] scan: DVD has 1 title(s)
[19:10:59] scan: scanning title 1
[19:10:59] scan: duration is 02:02:40 (7360400 ms)
[19:10:59] pgc_id: 1, pgn: 1: pgc: 00000218b40ec860
[19:10:59] scan: checking audio 1
[19:10:59] scan: audio channel is not active
[19:10:59] scan: checking audio 2
[19:10:59] scan: id=0x80bd, lang=Unknown (AC3), 3cc=und ext=0
[19:10:59] scan: title 1 has 9 chapters
[19:10:59] scan: chap 1, 900280 ms
[19:10:59] scan: chap 2, 899880 ms
[19:10:59] scan: chap 3, 900000 ms
[19:10:59] scan: chap 4, 900000 ms
[19:10:59] scan: chap 5, 899760 ms
[19:10:59] scan: chap 6, 900000 ms
[19:10:59] scan: chap 7, 900120 ms
[19:10:59] scan: chap 8, 899760 ms
[19:10:59] scan: chap 9, 160600 ms
[19:10:59] scan: aspect = 16:9
[19:10:59] scan: decoding previews for title 1
[19:10:59] scan: title angle(s) 1
VC E [19:11:22] Operation 'Ping' failed: System.OperationCanceledException: The operation was canceled.
   at System.IO.Pipes.PipeStream.PipeValueTaskSource.GetResult(Int16 token)
   at System.IO.Pipes.PipeStream.PipeValueTaskSource.System.Threading.Tasks.Sources.IValueTaskSource.GetResult(Int16 token)
   at System.Threading.Tasks.ValueTask.ValueTaskSourceAsTask.<>c.<.cctor>b__4_0(Object state)
--- End of stack trace from previous location ---
   at PipeMethodCalls.PipeStreamWrapper.SendMessageAsync(MessageType messageType, IMessage payloadObject, CancellationToken cancellationToken)
   at PipeMethodCalls.MethodInvoker`1.GetResponseAsync(SerializedPipeRequest request, CancellationToken cancellationToken)
   at PipeMethodCalls.MethodInvoker`1.GetResponseFromExpressionAsync(Expression expression, CancellationToken cancellationToken)
   at PipeMethodCalls.MethodInvoker`1.InvokeAsync[TResult](Expression`1 expression, CancellationToken cancellationToken)
   at VidCoder.RemoteProxyBase`2.<>c__DisplayClass41_0.<<PrepareWorkerProcessAsync>b__1>d.MoveNext()
VC E [19:11:22] Encode failed with code ErrorProcessCommunication
VC [19:11:22] Job completed (Elapsed Time: 2m 39s)

fbagnato avatar Jul 15 '24 09:07 fbagnato

Does it succeed when you go to Global Options -> Process and uncheck "Use worker process to encode"?

Also it would help if I had some more logs. Global Options -> Advanced -> Logging verbosity -> Extended, then look in %appdata%\VidCoder-Beta\Logs and get the "Encode" and "PipeServer Encode" logs.

RandomEngy avatar Jul 16 '24 13:07 RandomEngy

Hello RandomEngy,

Thanks for your reply.

Sorry I haven't replied earlier but although subscribed to notifications for this thread I didn't receive a notification so I didn't know you replied until I decided to check it days later.

Your suggestion of unchecking "Use worker process to encode" worked.

The encoding goes all the way and completes normally now.

I am now running the encode again with the Logging Verbosity set to Extended to get you the logs you requested.

I will post back once the encode concludes.

Regards,

fbagnato

fbagnato avatar Jul 21 '24 04:07 fbagnato

Hello RandomEngy,

OK, turned the "Use worker process to encode" back on and changed the Logging Verbosity set to Extended then reran the test encode which failed.

I have attached all the logs even though you only asked for the "Encode" and "PipeServer Encode" logs.

Hope they help!

Regards,

fbagnato 2024-07-22 13.47.31 Combined.txt 2024-07-22 13.48.06 Combined.txt 2024-07-22 13.48.06 General.txt 2024-07-22 13.48.26 Scan The Magnificent Seven.txt 2024-07-22 13.48.56 Encode The Magnificent Seven.mp4-failed.txt 2024-07-22 13.48.59 PipeServer Encode VidCoderWorker.43cb5f2c-90c8-4601-ab42-8f07ebaaeb71.txt

fbagnato avatar Jul 22 '24 04:07 fbagnato

Thanks for the report. There's some odd stuff happening there. For one, the inter-process messages appear to be delayed by 3 or 4 seconds. Also the progress events are coming in batches. I'm curious, how many cores does your CPU have?

I see the reason for the failure is finding an unexpected message type while reporting progress: it's likely offset in the communication stream, though that shouldn't happen.

Just in case it helps, I'm trying to land a change in HandBrake to make the progress reports less frequent: https://github.com/HandBrake/HandBrake/pull/6200 .

RandomEngy avatar Jul 22 '24 14:07 RandomEngy

Hello RandomEngy,

It is an Intel Core i5-3317U CPU @ 1.70GHz with 2 Cores and 4 Threads.

When I run a VidCoder encode, I have a few programs open and sometimes other things actively running. I rarely run an encode in a clean and quiet environment. I don't know if that is making the failures more frequent. However I can run Handbrake in the same sort of environment without failures.

So do I just wait for a new release of VidCoder then retry it again with "Use worker process to encode" checked, presuming that the problem has been fixed in Handbrake?

Regards,

fbagnato

fbagnato avatar Jul 22 '24 15:07 fbagnato

VidCoder 11.5 Beta includes a change that makes the progress reports less frequent when no updates were found. This might help you; let me know.

RandomEngy avatar Aug 03 '24 22:08 RandomEngy

Hello RandomEngy,

I installed VidCoder 11.5 Beta and ran a test encode.

The problem is still occurring.

Unticking "Use worker process to encode" ensures a full encode without failing.

Regards,

fbagnato

fbagnato avatar Aug 05 '24 02:08 fbagnato

I'm seeing this issue occasionally in 10.15 on normal encodes with "Use worker process to encode" enabled. Usually, a retry will succeed, but of course a lot of time has been wasted. It's a fairly recent problem for me, started sometime in the past few months. I'm reverting to 11.7 Beta to see if that helps. Log from a recent failure attached. 2024-11-11 15.23.18 Encode Hemingway (2021) - S01E03 - The Blank Page (1944-1961) (1080p AMZN WEB-DL x265 t3nzin) HEVC 25.mp4-failed.zip

JNavas2 avatar Nov 12 '24 00:11 JNavas2

Alas, while 11.7 Beta worked well on quite a few videos, it just failed the same way (log attached). UPDATE: Retry of that video succeeded. Is there anything else you would like from me? 2024-11-21 06.04.14 Encode failed.zip

JNavas2 avatar Nov 21 '24 15:11 JNavas2

Another 11.7 Beta failure. 2024-11-26 08.26.56 Encode failed.zip UPDATE: Simple retry succeeded.

JNavas2 avatar Nov 26 '24 17:11 JNavas2

Another 11.7 Beta failure.

Since that time I've had no failures. Of note is that I reinstalled Windows during that time, which might have resolved the issue.

JNavas2 avatar Dec 13 '24 14:12 JNavas2

I upgraded my computer to a relatively new laptop running Windows 11 on the AMD 7840U, which allows me to encode 2 videos at once more efficiently than one at a time, and since then I have done well over 100 encodes without incident, but today I had a failed encode (that was successful with retried). Full log is attached, but here's the essential part:

HB [07:15:57] Finished work at: Fri Feb 07 07:15:57 2025 [07:15:57] libhb: work result = 0 VC E [07:15:57] Encode failed. HandBrake reported no error but the expected output file was not found. VC [07:15:57] Job completed (Elapsed Time: 28m 43s)

There was a part file that was playable but not renamed.

LOG.zip

JNavas2 avatar Feb 07 '25 17:02 JNavas2

Thanks, this looks like a different error! I'm going to put some extra logging in for the output file it is expecting. That should narrow down the issue.

RandomEngy avatar Feb 23 '25 00:02 RandomEngy

Thanks. I've not seen this error again in well over 100 encodes.

JNavas2 avatar Feb 23 '25 01:02 JNavas2

Excellent. I added some extra logging in v12.0 Beta in case this happens again.

RandomEngy avatar Mar 01 '25 20:03 RandomEngy