DNxHD encoding issues

[Vininski]

Ok so I tested transcoding the same 3 files with the %s_original_name% added to the tape name, then again with it just added to the project name and then a third time with it added to both just for good measure. All tests resulted in unique "file_package_umid" for every file which is great but then sometimes just running the transcode again with the same settings can do this.

So then I run a whole batch with the %s_original_name% added to the tape/reel name and some reels are flawless but several have issues. I've run ffprobe on one of these and found that the "file_package_umid" is not the same as the file it is wrongly referencing. In this case when I isolated the offending mediafiles then imported, it wrongly referenced a clip that was not in seqeuence so it appears it can happed to any other clip in the reel.

See below that clip6 wrongly references clip1 from that reel but they do not have the same "file_package_umid".

package_umids.PNG (86.06 KiB) Viewed 11227 times

So far the change to the workflow seems to have stopped the umid conflict but I'm still having the same import issues :S

I'm really surprised that this isn't a more widespread issue as I would have thought FFAStrans would be used for Avid media by many users.

EDIT:
While the "file_package_umid" is unique, I started comparing other fields and found the "material_package_umid" of clips 6 & 1 are identical. Then I found this discussion on bmxlib:https://sourceforge.net/p/bmxlib/discus ... it=25#e8c8
If I'm understanding this thread correctly, it seems that an important umid that Avid uses to identify files is calculated based on the system clock so that files encoded in parallel could be conflicting. That would be diasterous in a farm like setup such as this! Most of the jargon goes way over my head but does this make sense to anyone else?

I'm thinking perhaps even if I just limit each machine to a single job at a time it could reduce the probability of jobs starting at the same time if the system clocks aren't all perfectly synchronised. In theory running one machine with 1 job at a time would make it impossible for time based conflicts so I'll try that on a small batch when I get the chance.

[emcodem]

Hey Vinny,

very nice finding in the bmx discussion group. I had a look in the source code of the mentioned part in libMXF/mxf_avid.c and i see there area already some hacks around this, so it looks like this topic did not come up the first time.
To be honest, i did not spend the time to check if the UMID's are valid after this patch, but for your convenience (not sure if you are able to do this), i applied the same patch as the user did in the BMX discussion and uploaded the resulting build here. You can use it and replace the default bmxtranswrap that comes with ffastrans for start. Please let us know if this solves your problem. If yes, i can probably create a patch that involves a commandline switch to force this behaviour and send them to bmx guys for merging (but they are not too active anymore ^^ so we probably better go with a custom copy of the source anyway)

https://drive.google.com/open?id=1dqwWf ... yjy6nvLY8e

Please know that the visual studio 2010 x86 redist is needed to run this build (i believe it is neccessary for the original build as well): https://www.microsoft.com/en-us/downloa ... px?id=5555

I don't really wonder that this only hits a few users, first there are not too many Avid users out there and only some of them use ffastrans. Second from this small number of users the chances that they run workflows that start in the same second is even smaller. Same for BMX users. The chances that anyone hits this problem AND is willing to invest the time to go to the bottom of the problems goes in direction 0

Let me know

[Vininski]

emcodem you're a legend! I'll test this out as soon as I can.

I guess you're right about the number of users with this use case being tiny, I only found out about the program after searching for network farming solutions for quite some time of which there was not a lot to find overall on it's own.

[emcodem]

Just to let you know, i just tested very quickly and found out that i could reproduce your problem with the same MP Umid being generated when 2 transwrapping processes start at the same time (it was hard to reproduce actually but 2 out of 3 mostly matched).
Using the bmxtranswrap version i uploaded before, the FilePackage UMID and the MP UMID seem to be totally different (unique), independently of the Project and Tape name and Time of day.

[Vininski]

I've run a couple days worth through with the patched file and so far no issues at all, this is fantastic!. I owe you a carton of beer!!

[Vininski]

Might have spoken too soon. I appear to be having another seemingly unrelated issue that has been occuring before and after the patched file was implemented. There's a few long interview clips (ranging from 0.75-1.5hrs) that have transcoded and imported but are shorter than their original sources. I haven't seen any errors pop up from FFASTrans but even after re-transcoding the file is still short (2nd pass was even shorter than the 1st, 3rd pass the file doesn't even import or playback)

Here's the ffprobe from the 3rd pass. Unfourtunately I can't upload it due to the file size and the subject material.

C:\Users\Editor>ffprobe "V:\Avid MediaFiles\MXF\3\FRS3_SD35_E020_Clip0001_v1.mxf
"
ffprobe version N-92820-gd702600350 Copyright (c) 2007-2018 the FFmpeg developer
s
built with gcc 8.2.1 (GCC) 20181201
configuration: --disable-static --enable-shared --enable-gpl --enable-version3
--enable-sdl2 --enable-fontconfig --enable-gnutls --enable-iconv --enable-libas
s --enable-libbluray --enable-libfreetype --enable-libmp3lame --enable-libopenco
re-amrnb --enable-libopencore-amrwb --enable-libopenjpeg --enable-libopus --enab
le-libshine --enable-libsnappy --enable-libsoxr --enable-libtheora --enable-libt
wolame --enable-libvpx --enable-libwavpack --enable-libwebp --enable-libx264 --e
nable-libx265 --enable-libxml2 --enable-libzimg --enable-lzma --enable-zlib --en
able-gmp --enable-libvidstab --enable-libvorbis --enable-libvo-amrwbenc --enable
-libmysofa --enable-libspeex --enable-libxvid --enable-libaom --enable-libmfx --
enable-amf --enable-ffnvcodec --enable-cuvid --enable-d3d11va --enable-nvenc --e
nable-nvdec --enable-dxva2 --enable-avisynth --enable-libopenmpt
libavutil 56. 25.100 / 56. 25.100
libavcodec 58. 42.104 / 58. 42.104
libavformat 58. 25.100 / 58. 25.100
libavdevice 58. 6.101 / 58. 6.101
libavfilter 7. 46.101 / 7. 46.101
libswscale 5. 4.100 / 5. 4.100
libswresample 3. 4.100 / 3. 4.100
libpostproc 55. 4.100 / 55. 4.100
[mxf @ 000000d2ded85e40] broken or empty index
[mxf @ 000000d2ded85e40] Could not find codec parameters for stream 0 (Video: dn
xhd, none(bt709/unknown/unknown, progressive), 1920x1080): unspecified pixel for
mat
Consider increasing the value for the 'analyzeduration' and 'probesize' options
Input #0, mxf, from 'V:\Avid MediaFiles\MXF\3\FRS3_SD35_E020_Clip0001_v1.mxf':
Metadata:
project_name : FRS3
uid : c2c72853-3ab3-48f1-932c-775aef0a6a45
generation_uid : ccedf547-2857-4d7a-9d54-c9df1e947432
modification_date: 2019-07-18T05:18:11.656000Z
company_name : BBC
product_name : bmx
product_version : 0.1.3 (scm snap1708)
product_uid : b8604d31-2e15-4799-a3c6-047ed0e6f9a1
application_platform: libMXF (Win32)
material_package_umid: 0x060A2B340101010501010F20130000004BF93059C93F428FBEB
F310E518B3FFC
material_package_name: FRS3_SD35_E020_Clip0001
Duration: N/A, start: 0.000000, bitrate: N/A
Stream #0:0: Video: dnxhd, none(bt709/unknown/unknown, progressive), 1920x10
80, SAR 1:1 DAR 16:9, 25 tbr, 25 tbn, 25 tbc
Metadata:
file_package_umid: 0x060A2B340101010501010F201300000040D4FD3E015A4F3FA8B74
734C5AE5733
track_name : V1
reel_umid : 0x060A2B340101010501010F2013000000DED9EF8535BB4936A20FB6
B12CC1263C
reel_name : FRS3_SD35_E020
timecode : 13:41:17:10
Stream #0:1: Data: none
Metadata:
file_package_umid: 0x060A2B340101010501010F2013000000D667C21990DD442AA61B0
6CE4B5AE698
track_name : A1
data_type : audio
Stream #0:2: Data: none
Metadata:
file_package_umid: 0x060A2B340101010501010F20130000005CC0AE4ABF81468C8DB04
61404C69FAA
track_name : A2
data_type : audio
Stream #0:3: Data: none
Metadata:
file_package_umid: 0x060A2B340101010501010F2013000000E7A1418DE4F14BDD8BCEC
E136BA96BEC
track_name : A3
data_type : audio
Stream #0:4: Data: none
Metadata:
file_package_umid: 0x060A2B340101010501010F2013000000F300AE6DD602476EBA8AF
9AB3E375F29
track_name : A4
data_type : audio
Unsupported codec with id 0 for input stream 1
Unsupported codec with id 0 for input stream 2
Unsupported codec with id 0 for input stream 3
Unsupported codec with id 0 for input stream 4

AFAIK this has happened to 4 IV clips, all over 30mins in length. 3 of 4 I have been able to re-transcode to fix the issue. I thought it was caused by the watch folder picking up files that had not transferred completely. While I have "Check once" ticked, it seems if you pause a file transfer then it is not aware and will process the partial file. But I have watched the transfer complete before it started on this 3rd pass so I've now ruled it out as the sole cause.

[emcodem]

Hey Vinny
well that issue might be a little harder to debug as it might most likely be connected to some local system issues.
The basics for debugging this is the knowledge that more or less only ffmpeg can create this issue, ffastrans might not be involved at all (this is the first thing to prove). The reason for you not getting an error is that ffastrans uses ffprobe after the transcode to check if the output can be parsed by ffprobe and as ffprobe actually spits out some data for the short files, i guess ffastrans reports back that everything is OK.

So in the end i'd like to start debugging this just as another active case: viewtopic.php?f=5&t=899&start=10#p3968


In the post above, i asked Thomas to enable logging and zip/send us the log files of a failed job. If you read on some messages, you see that i found out that the _ffreport.txt file from the encoding in question just stopped unexpectedly. This points in direction there was something wrong with the ffmpeg encode and i asked Thomas in the end to try and reproduce to execute the ffmpeg command (found in the _ffreport.txt) manually - check if the issue is reproduceable this way.

Anyway, to start, we need to do the same as for Thoma's case: analyze, simplify and reproduce. First, analyze by collecting logs of a failed job as described in the link above, then simplify by trying to reproduce using ffmpeg only and when it is reproduceable, we are pretty close to a solution.
At the same time, i'd like to know if the last few bytes of the "too short" files in a hex editor look like this screenhot. ...i believe you could check only the last byte, it should probably always have the hex value "41" but also the whole surrounding bytes with all the zeros should look alike. If you dont have a hex editor installed, you can use my favourite "HXD" or use the online version hexed.it - it will not upload the file to their severs

lastbytes_.png (14.7 KiB) Viewed 11148 times

[Vininski]

Starting with the results from the hex editor:
3rd pass, file does not playback or import, does not end in 41
4th pass, file does playback and import, does end in 41 (with A as pictured above)

I couldn't find the logs for the failed export as there were many other folders but I'll keep running it until it fails again and upload. Are the logs from the successfull 4th pass of any use?

[emcodem]

Great, the logs will hopefully give some insight.
It is not a surprise that the defective file from pass 3 looks different in hexeditor; this indicates that the transcoding process was interrrupted while it was running. What i didn't get by now if the duration of file from pass 4 (which looks good in hex editor) was OK or not. I wonder how files with shorter duration look like, also some ffprobe output from a working file with shorter duration might give some insight.

cheers!

[Vininski]

Logs from 4th pass, which was the correct duration.
https://drive.google.com/open?id=1Y2sBg ... 279eyhlzRC (everything except for the 44GB mxf file. I presume this is the file it creates before splitting the video and audio tracks?)

I've run it 3 more times and could not get it to reproduce the issue. Then when proceeding to process a whole day I've found multiple that are shorter than the originals and did import.

Here's the ffprobe output and logs for one of those clips:

C:\Users\Editor>ffprobe "V:\Avid MediaFiles\DUD\SD38_B031_short\FRS3_SD38_B031_C
lip0058_v1.mxf"
ffprobe version N-92820-gd702600350 Copyright (c) 2007-2018 the FFmpeg developer
s
built with gcc 8.2.1 (GCC) 20181201
configuration: --disable-static --enable-shared --enable-gpl --enable-version3
--enable-sdl2 --enable-fontconfig --enable-gnutls --enable-iconv --enable-libas
s --enable-libbluray --enable-libfreetype --enable-libmp3lame --enable-libopenco
re-amrnb --enable-libopencore-amrwb --enable-libopenjpeg --enable-libopus --enab
le-libshine --enable-libsnappy --enable-libsoxr --enable-libtheora --enable-libt
wolame --enable-libvpx --enable-libwavpack --enable-libwebp --enable-libx264 --e
nable-libx265 --enable-libxml2 --enable-libzimg --enable-lzma --enable-zlib --en
able-gmp --enable-libvidstab --enable-libvorbis --enable-libvo-amrwbenc --enable
-libmysofa --enable-libspeex --enable-libxvid --enable-libaom --enable-libmfx --
enable-amf --enable-ffnvcodec --enable-cuvid --enable-d3d11va --enable-nvenc --e
nable-nvdec --enable-dxva2 --enable-avisynth --enable-libopenmpt
libavutil 56. 25.100 / 56. 25.100
libavcodec 58. 42.104 / 58. 42.104
libavformat 58. 25.100 / 58. 25.100
libavdevice 58. 6.101 / 58. 6.101
libavfilter 7. 46.101 / 7. 46.101
libswscale 5. 4.100 / 5. 4.100
libswresample 3. 4.100 / 3. 4.100
libpostproc 55. 4.100 / 55. 4.100
Input #0, mxf, from 'V:\Avid MediaFiles\DUD\SD38_B031_short\FRS3_SD38_B031_Clip0
058_v1.mxf':
Metadata:
project_name : FRS3
uid : a4161948-7b5f-4528-aeff-c578b18224f2
generation_uid : 11b3d985-fd58-4435-bbfd-1ec4436729ed
modification_date: 2019-07-22T02:35:57.628000Z
company_name : BBC
product_name : bmx
product_version : 0.1.3 (scm snap1708)
product_uid : b8604d31-2e15-4799-a3c6-047ed0e6f9a1
application_platform: libMXF (Win32)
material_package_umid: 0x060A2B340101010501010F2013000000CA4C6892C9B1412EBA6
DC942FD60301D
material_package_name: FRS3_SD38_B031_Clip0058
Duration: 00:12:09.20, start: 0.000000, bitrate: 121246 kb/s
Stream #0:0: Video: dnxhd (DNXHD), yuv422p(bt709/unknown/unknown, progressiv
e), 1920x1080, SAR 1:1 DAR 16:9, 25 fps, 25 tbr, 25 tbn, 25 tbc
Metadata:
file_package_umid: 0x060A2B340101010501010F201300000063902AD57E1B42D3AAC73
49C4BD8D0D3
track_name : V1
reel_umid : 0x060A2B340101010501010F20130000005190FFC616724D6681055E
46996B6097
reel_name : FRS3_SD38_B031
timecode : 08:06:31:11
Stream #0:1: Data: none
Metadata:
file_package_umid: 0x060A2B340101010501010F201300000018D13DE03A44413BB318D
FE32A6FDBF0
track_name : A1
data_type : audio
Stream #0:2: Data: none
Metadata:
file_package_umid: 0x060A2B340101010501010F20130000004854713778D04BAABC08F
47217D87096
track_name : A2
data_type : audio
Stream #0:3: Data: none
Metadata:
file_package_umid: 0x060A2B340101010501010F20130000005228AA4994C74320A1F12
1498529CCD9
track_name : A3
data_type : audio
Stream #0:4: Data: none
Metadata:
file_package_umid: 0x060A2B340101010501010F201300000004D050AF7DB74B50BFE31
C2E6AAB5C9D
track_name : A4
data_type : audio
Unsupported codec with id 0 for input stream 1
Unsupported codec with id 0 for input stream 2
Unsupported codec with id 0 for input stream 3
Unsupported codec with id 0 for input stream 4

Here's the link for the FFAStrans logs for this file:
https://drive.google.com/open?id=1cLW6d ... rByH-hI8H4