BUG: (v5.21) VC doesn't delete (some?/all?) source files

[bcurran3]

Just ran a batch through VC 5.21 and it did pop up asking to delete source files... BUT it didn't delete them.

I have two theories:

1 - problems deleting from mapped network drives. 2 - problems based on extension (mpg)

Too many files to go through in a big directory of files to know for sure. I'll try hit the logs later to see what is going on. I'm transcoding a mixed batch of AVI, MOV, MTS, MPG files to MP4 and, if this last round was a mixed batch, it's possible that some files of certain extensions are being deleted but .mpg's are not.

[RandomEngy]

Check the General log. If it failed to delete it should tell you why.

[bcurran3]

"real time update" - A batch of 23 transcodes just finished. I clicked the X on the Completed tab and I have a Confirm delete message box asking me "Are you sure you want to delete 15 source files(s)/folder(s)? Again, the completed tab is at 23.

x_general.txt is full of "Starting encode" and "Job completed" messages for each file and no errors.

EDIT: I looked at the scan and encode logs of 4 random transcodes from this batch. Each had the normal DVD and BluRay errors as these are files, not discs. Three had no apparent errors, one had multiple [19:48:27] hb_sample_pts: couldn't find video packet near xxx errors and that transcode (marked successful) was truncated by a few minutes. I confirmed the source appears to be bad and only plays about 3/4.

[RandomEngy]

I added some more logging in 6.11 Beta. It should break down the specific reasons why a file wasn't included in the "delete" list. If you have that version it will show up in the General log.

[bcurran3]

Some more info, from v5.21:

Looking at the logs, I have some -succeeded.txt and some that don't have the appended -succeeded.txt. Though it seems that all the transcodes are succeeding, they're not being logged that way. I haven't directly correlated this to the finished list, but I'm guessing it's related. (I'm in a big batch of very timing consuming transcodes.)

tail example 1 of MPG -> MP4 transcode logs that does NOT have -succeeded.txt appended:

[19:55:35] file is MPEG Program Stream [19:55:35] Probing 1 unknown stream [19:55:35] Probe: Found stream mpegvideo. stream id 0xe0-0x0 [19:55:35] sync: expecting 55393 video frames [19:55:35] encx264: min-keyint: 30, keyint: 300 [19:55:35] encx264: encoding at constant RF 20.000000 [19:55:35] encx264: unparsed options: level=4.0:ref=4:direct=auto:subme=8:trellis=2:vbv-bufsize=31250:vbv-maxrate=25000:rc-lookahead=50 x264 [info]: x264 [info]: x264 [info]: [19:55:35] sync: first pts video is 0 [19:55:35] sync: first pts audio 0x8000bd is 0 [19:55:35] sync: first pts audio 0x8000bd is 0

tail example 2 of MPG -> MP4 transcode logs that does NOT have -succeeded.txt appended:

[19:45:23] file is MPEG Program Stream [19:45:24] Probing 1 unknown stream [19:45:24] Probe: Found stream mpegvideo. stream id 0xe0-0x0 [19:45:24] sync: expecting 88529 video frames [19:45:24] encx264: min-keyint: 30, keyint: 300 [19:45:24] encx264: encoding at constant RF 20.000000 [19:45:24] encx264: unparsed options: level=4.0:ref=4:direct=auto:subme=8:trellis=2:vbv-bufsize=31250:vbv-maxrate=25000:rc-lookahead=50 x264 [info]: x264 [info]: x264 [info]: [19:45:24] sync: first pts video is 0 [19:45:24] sync: first pts audio 0x8000bd is 0 [19:45:24] sync: first pts audio 0x8000bd is 0

tail example 1 of MPG -> MP4 transcode logs that DOES have -succeeded.txt appended:

[18:31:40] file is MPEG Program Stream [18:31:40] Probing 1 unknown stream [18:31:40] Probe: Found stream mpegvideo. stream id 0xe0-0x0 [18:31:40] sync: expecting 13110 video frames [18:31:40] encx264: min-keyint: 30, keyint: 300 [18:31:40] encx264: encoding at constant RF 20.000000 [18:31:40] encx264: unparsed options: level=4.0:ref=5:direct=auto:subme=8:trellis=2:vbv-bufsize=31250:vbv-maxrate=25000:rc-lookahead=50 x264 [info]: x264 [info]: x264 [info]: [18:31:40] sync: first pts video is 0 [18:31:40] sync: first pts audio 0xc0 is 0 [18:42:36] reader: done. 1 scr changes [18:42:42] work: average encoding speed for job is 19.915665 fps [18:42:43] comb detect: heavy 12700 | light 152 | uncombed 260 | total 13112 [18:42:43] decomb: deinterlaced 12700 | blended 152 | unfiltered 260 | total 13112 [18:42:43] vfr: 13112 frames output, 0 dropped and 0 duped for CFR/PFR [18:42:43] vfr: lost time: 0 (0 frames) [18:42:43] vfr: gained time: 0 (0 frames) (0 not accounted for) [18:42:43] stream: 216417 good frames, 0 errors (0%) [18:42:43] mp2-decoder done: 18230 frames, 0 decoder errors [18:42:43] mpeg2video-decoder done: 13112 frames, 0 decoder errors [18:42:43] sync: got 13112 frames, 13110 expected [18:42:43] sync: framerate min 29.970 fps, max 29.970 fps, avg 29.970 fps [aac @ 0000024fe8c8e340] Qavg: 174.301 x264 [info]: x264 [info]: x264 [info]: x264 [info]: x264 [info]: x264 [info]: x264 [info]: x264 [info]: x264 [info]: x264 [info]: x264 [info]: x264 [info]: x264 [info]: x264 [info]: x264 [info]: x264 [info]: x264 [info]: x264 [info]: x264 [info]: [18:42:43] mux: track 0, 13112 frames, 90716023 bytes, 1658.67 kbps, fifo 2048 [18:42:43] mux: track 1, 20509 frames, 8787145 bytes, 160.67 kbps, fifo 4096 [18:42:43] Finished work at: Fri Aug 14 18:42:43 2020 [18:42:43] libhb: work result = 0

Job completed (Elapsed Time: 11m 12s)

tail example 2 of MPG -> MP4 transcode logs that DOES have -succeeded.txt appended:

[16:30:08] file is MPEG Program Stream [16:30:08] Probing 1 unknown stream [16:30:08] Probe: Found stream mpegvideo. stream id 0xe0-0x0 [16:30:08] sync: expecting 45048 video frames [16:30:08] encx264: min-keyint: 30, keyint: 300 [16:30:08] encx264: encoding at constant RF 20.000000 [16:30:08] encx264: unparsed options: level=4.0:ref=4:direct=auto:subme=8:trellis=2:vbv-bufsize=31250:vbv-maxrate=25000:rc-lookahead=50 x264 [info]: x264 [info]: x264 [info]: [16:30:08] sync: first pts video is 0 [16:30:09] sync: first pts audio 0x8000bd is 0 [16:30:09] sync: first pts audio 0x8000bd is 0 [19:44:33] reader: done. 1 scr changes [19:45:13] work: average encoding speed for job is 3.857516 fps [19:45:13] comb detect: heavy 17114 | light 16516 | uncombed 11418 | total 45048 [19:45:13] decomb: deinterlaced 17114 | blended 16516 | unfiltered 11418 | total 45048 [19:45:13] vfr: 45048 frames output, 0 dropped and 0 duped for CFR/PFR [19:45:13] vfr: lost time: 0 (0 frames) [19:45:13] vfr: gained time: 0 (0 frames) (0 not accounted for) [19:45:13] stream: 2230275 good frames, 0 errors (0%) [19:45:13] ac3-decoder done: 46972 frames, 0 decoder errors [19:45:13] ac3-decoder done: 46972 frames, 0 decoder errors [19:45:13] mpeg2video-decoder done: 45048 frames, 0 decoder errors [19:45:13] sync: got 45048 frames, 45048 expected [19:45:13] sync: framerate min 29.970 fps, max 29.970 fps, avg 29.970 fps [aac @ 000001f6981fe9c0] Qavg: 199.697 x264 [info]: x264 [info]: x264 [info]: x264 [info]: x264 [info]: x264 [info]: x264 [info]: x264 [info]: x264 [info]: x264 [info]: x264 [info]: x264 [info]: x264 [info]: x264 [info]: x264 [info]: x264 [info]: x264 [info]: x264 [info]: x264 [info]: [19:45:13] mux: track 0, 45048 frames, 1735360212 bytes, 9235.95 kbps, fifo 512 [19:45:13] mux: track 1, 70459 frames, 30171210 bytes, 160.58 kbps, fifo 1024 [19:45:13] mux: track 2, 46972 frames, 48099328 bytes, 255.99 kbps, fifo 512 [19:45:13] Finished work at: Fri Aug 14 19:45:13 2020 [19:45:13] libhb: work result = 0

Job completed (Elapsed Time: 3h 15m)

Seems the logging stops for some reason after sync: first pts audio 0x8000bd is 0

If this was the DOS days I'd change my up the files statement in my CONFIG.SYS. LOL!

[RandomEngy]

The log just stopping is odd. I'd like to know what the behavior was for the main application. Shown as failed? Did it hang? Did the UI process crash? If there is a crash in the encoding process, the main process should detect that and log that outcome.

Do you have the worker process enabled?

[bcurran3]

I run 4 worker processes at a time.

Files encoded and reported as succeeded. No hangs of the program. Everything seemed fine except not asked to delete all the finished encodes and the logging stopped as show.

All files were on a network drive. All files had the same permissions.

The only thing different about this couple hundred files versus thousands of others is the file permissions. These were more restrictive but fully access to the current user / vidcoder running in the userspace.

[RandomEngy]

Hmm okay. Well, I'll wait on logs from a recent beta; will be much easier to debug with that information.

[bcurran3]

Unfortunately I'm done with that batch and it's only happened related to the files there. :( I will let you know if it happens again, but I'm not using the beta at the moment.