search

cth103 / dcpomatic

DCP-o-matic repository: main is the development branch (where v2.16.x versions are being made) and v2.17.x has the v2.17.x "unstable" versions (main is merged there every so often).
https://dcpomatic.com/
GNU General Public License v2.0
111 stars 23 forks source link

error -13 when converting an encrypted 3D DCP into a clear DCP #21

Open wunderbarb opened 1 year ago

wunderbarb commented 1 year ago

The crash occurs when converting a 3D encrypted DCP into a clear DCP (providing the corresponding KDM). The error is terminate caught unhandled exception. what(): could not open file to compute digest (/mnt/techdev-nas/DCP2/Dolby_3D_DCPs/rnd/Movie/Movie_FTR-1_S_XX-XX_71-HI-VI-IAB_2K_20230918_SMPTE_OV/pcm_18e657ad-a24e-496a-b1c5-e1d6a2270918.mxf) (error -13) The DCP is not transcoded as the target project uses the characteristics from the source DCP. An example of the command dcpomatic2_create -t Dolby3D -n Movie -c FTR --kdm kdm_Movie_FTR_EN-XX_Atmos_430-2_LEAF_Sony_2023-08-31_2023-11-30_DGB.xml Movie_FTR-2-3D-DVis_S_EN-XX_OV_51-Atmos_2K_SPE_20161213_DLB_SMPTE-3D_OV/ -o ../rnd/Movie dcpomatic2_cli ../rnd/Movie The operation does the full decryption, "conversion," transfer in the OV directory, and crashes at the index calculation. The end of the log file is as follows: Fri 15 Sep 2023 09:53:41 AM PDT: Transcode job starting Fri 15 Sep 2023 09:53:41 AM PDT: Sub-job Encoding starting Fri 15 Sep 2023 11:08:05 AM PDT: Clearing queue of 0 Fri 15 Sep 2023 11:08:05 AM PDT: Terminating encoder threads Fri 15 Sep 2023 11:08:05 AM PDT: Mopping up 0 Fri 15 Sep 2023 11:08:05 AM PDT: Terminating writer thread Fri 15 Sep 2023 11:08:05 AM PDT: Finishing ReelWriters Fri 15 Sep 2023 11:08:28 AM PDT: Writing XML Fri 15 Sep 2023 11:08:28 AM PDT: Sub-job Computing digests starting I have tested with two different DCPS (different movies). Both crashed with the same error. I know the DCPs are OK, as they were used in DCI projectors. I performed the same operation with a non-encrypted, 2D DCP. In that case, the operation succeeded. The same behavior occurs with the GUI. Using the most recent candidate release v2.16.64 on Ubuntu 22.04.

cth103 commented 1 year ago

That's a bit odd. Does the file in the error (/mnt/techdev-nas/DCP2/Dolby_3D_DCPs/rnd/Movie/Movie_FTR-1_S_XX-XX_71-HI-VI-IAB_2K_20230918_SMPTE_OV/pcm_18e657ad-a24e-496a-b1c5-e1d6a2270918.mxf) exist just after the error is given? Error -13 is a rather general "file open failure" error.

wunderbarb commented 1 year ago

I guessed so. After the crash, the file exists. It does not have a zero size, and I checked if there were any typo. When I check the "generated" files they seem OK. They are even moved from video to the OV.

cth103 commented 1 year ago

That is strange. This could be an example of a very elusive bug that I think we have seen on and off for years, namely strange failures to open files that are on NAS devices. If it is reproducible for you it would be great if I could prepare you a test build to get to the bottom of it. Let me know if you think you'd have time for that.

wunderbarb commented 1 year ago

It seems 100% reproducible. I would run the instrumented SW with pleasure.

wunderbarb commented 1 year ago

Meanwhile, we will try to reproduce with a local storage rather than a NAS.

cth103 commented 1 year ago

Great, within the hour there should be a new .deb under here which should give a little more detail (e.g. the actual error code that open is returning).

cth103 commented 1 year ago

The build is here now.

wunderbarb commented 1 year ago

I run the new version and it crashed. The last lines displayed at the console Transcoding Movie; Computing digests: 5%; 47m remaining; finishing at 11:49 -> Kumu::FileReader::OpenRead /mnt/techdev-nas/DCP2/Dolby_3D_DCPs/rnd/MovieTry3/Movie_FTR-1_S_XX-XX_71-HI-VI-IAB_2K_20230919_SMPTE_OV/pcm_453439ca-fb67-4fe7-9229-b819d7d8ca43.mxf open failed with 13 terminate caught unhandled exception. what(): could not open file to compute digest (/mnt/techdev-nas/DCP2/Dolby_3D_DCPs/rnd/MovieTry3/Movie_FTR-1_S_XX-XX_71-HI-VI-IAB_2K_20230919_SMPTE_OV/pcm_453439ca-fb67-4fe7-9229-b819d7d8ca43.mxf) (error -13) Aborted (core dumped) When listing the content of the OV directory atmos_07c580e2-14c9-46b0-8cf1-ae93347df3b9.mxf j2c_0eb313c1-4e8e-42fe-b91e-ea59df781b33.mxf pcm_36f557eb-7485-4aaa-9812-782cd8bdbe97.mxf atmos_5118d701-76e1-40ad-9a2d-bedb19a952ce.mxf j2c_3ba41931-8b38-4b59-ab12-e3b714effff5.mxf pcm_40b2d51e-fded-4cf6-8c4b-a6893145ec2a.mxf atmos_5eee4eee-733d-43d4-894d-2dd3041913ad.mxf j2c_42202e63-6e65-46c4-b556-e76a587e7241.mxf pcm_453439ca-fb67-4fe7-9229-b819d7d8ca43.mxf atmos_6b9ef29d-5cdc-4400-95cc-68249e9c154c.mxf j2c_424e8a70-d473-4f25-82df-e70173639c3c.mxf pcm_58b18428-3e20-46ae-b986-a51e541a3640.mxf atmos_98ac21c1-46d7-488e-8435-5ea33f524955.mxf j2c_486ec3d8-cd32-4e22-9cb5-a26bb8547cd3.mxf pcm_7aebeeb3-f143-43fe-9fae-0c93a0661108.mxf atmos_d5c7045c-cc21-4b80-b3d1-dceddaa8096a.mxf j2c_6c9adacf-30cc-4169-bb11-163e0627b85a.mxf pcm_860896e0-f5eb-4784-9640-acb3ca81421a.mxf atmos_d9aa354d-55f7-4359-badb-35ce38f150b1.mxf j2c_84c1ef8e-82ad-4347-bb08-b1e253370887.mxf pcm_c4e24164-db23-4f12-a657-86a8c54887ca.mxf atmos_f146a749-a1f7-4869-8cae-2adbf2d25d5a.mxf j2c_9f299e48-ff19-422f-97e8-f2cf069fef3e.mxf pcm_d777071f-0615-49b2-b8e4-13f75a6db7cf.mxf the file is present.

cth103 commented 1 year ago

Thanks - that gives the precise error as 13 EACCES "permission denied". I guess if you do something like strings /mnt/techdev-nas/DCP2/Dolby_3D_DCPs/rnd/MovieTry3/Movie_FTR-1_S_XX-XX_71-HI-VI-IAB_2K_20230919_SMPTE_OV/pcm_453439ca-fb67-4fe7-9229-b819d7d8ca43.mxf at the terminal you get no error?

cth103 commented 1 year ago

Is the NAS mounted using CIFS/samba?

wunderbarb commented 1 year ago

IT is mounted as CIFS

wunderbarb commented 1 year ago

And yes of course strings operates properly.

cth103 commented 1 year ago

I don't suppose there's anything interesting in the dmesg/syslog of the client, or any logs on the NAS that would indicate why access is denied to this file one minute, and then allowed the next?

wunderbarb commented 1 year ago

Let me have a look.

wunderbarb commented 1 year ago

Let me have a look.

Nothing.

wunderbarb commented 1 year ago

Meanwhile, we will try to reproduce with a local storage rather than a NAS.

The same operation using local storage did succeed which seems to confirm that the issue is when using the NAS.

cth103 commented 1 year ago

Thanks. I'm wondering if something funny is going on when the audio MXF is closed after being written. If you have a second, perhaps you could install this new build and try again.

wunderbarb commented 1 year ago

It's running. I will report the answer tomorrow morning. Thanks

wunderbarb commented 1 year ago

It crashed. Here is what appeared on the console after Encoding -> Kumu::FileReader::OpenRead /mnt/techdev-nas/DCP2/Dolby_3D_DCPs/src/Movie_FTR-2-3D-DVis_S_EN-XX_OV_51-Atmos_2K_SPE_20161213_DLB_SMPTE-3D_OV/189740_Movie_smpTranscoding Movie; Encoding: 99%; 29s remaining; finishing at 17:23; 167057/167060 frames; 0.1 fps -> Kumu::FileReader::OpenRead /mnt/techdev-nas/DCP2/Dolby_3D_DCPs/rnd/MovieTry4/Movie_FTR-1_S_XX-XX_71-HI-VI-IAB_2K_20230919_SMPTE_OV/j2c_d9413c3a-f125-40cd-973e-517089c6f1ed.mxf -> Kumu::FileReader::OpenRead /mnt/techdev-nas/DCP2/Dolby_3D_DCPs/rnd/MovieTry4/Movie_FTR-1_S_XX-XX_71-HI-VI-IAB_2K_20230919_SMPTE_OV/j2c_526c2307-1753-4530-8fd9-7c75454afe65.mxf -> Kumu::FileReader::OpenRead /mnt/techdev-nas/DCP2/Dolby_3D_DCPs/rnd/MovieTry4/Movie_FTR-1_S_XX-XX_71-HI-VI-IAB_2K_20230919_SMPTE_OV/j2c_10c1e886-d88f-4767-abc5-cbbda074cae0.mxf -> Kumu::FileReader::OpenRead /mnt/techdev-nas/DCP2/Dolby_3D_DCPs/rnd/MovieTry4/Movie_FTR-1_S_XX-XX_71-HI-VI-IAB_2K_20230919_SMPTE_OV/j2c_7a4b90fa-196f-4b66-92db-5ac2012e04ea.mxf -> Kumu::FileReader::OpenRead /mnt/techdev-nas/DCP2/Dolby_3D_DCPs/rnd/MovieTry4/Movie_FTR-1_S_XX-XX_71-HI-VI-IAB_2K_20230919_SMPTE_OV/j2c_8b3f3c11-33c2-4693-b34b-1fd88d2f4975.mxf -> Kumu::FileReader::OpenRead /mnt/techdev-nas/DCP2/Dolby_3D_DCPs/rnd/MovieTry4/Movie_FTR-1_S_XX-XX_71-HI-VI-IAB_2K_20230919_SMPTE_OV/j2c_edc5651e-07ef-41e6-82bc-639cdd5910ca.mxf -> Kumu::FileReader::OpenRead /mnt/techdev-nas/DCP2/Dolby_3D_DCPs/rnd/MovieTry4/Movie_FTR-1_S_XX-XX_71-HI-VI-IAB_2K_20230919_SMPTE_OV/j2c_80244928-c185-46c2-b8c7-acfa99e724c0.mxf -> Kumu::FileReader::OpenRead /mnt/techdev-nas/DCP2/Dolby_3D_DCPs/rnd/MovieTry4/Movie_FTR-1_S_XX-XX_71-HI-VI-IAB_2K_20230919_SMPTE_OV/j2c_a2292d6d-34d4-4e5b-9Transcoding Movie; Computing digests: 20%; 12m remaining; finishing at 17:37 -> Kumu::FileReader::OpenRead /mnt/techdev-nas/DCP2/Dolby_3D_DCPs/rnd/MovieTry4/Movie_FTR-1_S_XX-XX_71-HI-VI-IAB_2K_20230919_SMPTE_OV/pcm_a3fbccd5-296e-406b-bTranscoding Movie; Computing digests: 25%; 10m remaining; finishing at 17:36 -> Kumu::FileReader::OpenRead /mnt/techdev-nas/DCP2/Dolby_3D_DCPs/rnd/MovieTry4/Movie_FTR-1_S_XX-XX_71-HI-VI-IAB_2K_20230919_SMPTE_OV/pcm_6639a315-8b21-4355-bc8c-779706b48362.mxf -> Kumu::FileReader::OpenRead /mnt/techdev-nas/DCP2/Dolby_3D_DCPs/rnd/MovieTry4/Movie_FTR-1_S_XX-XX_71-HI-VI-IAB_2K_20230919_SMPTE_OV/pcm_f84fa27f-a2af-4713-9c3d-80db59ef11a9.mxf open failed with 13 terminate caught unhandled exception. what(): could not open file to compute digest (/mnt/techdev-nas/DCP2/Dolby_3D_DCPs/rnd/MovieTry4/Movie_FTR-1_S_XX-XX_71-HI-VI-IAB_2K_20230919_SMPTE_OV/pcm_f84fa27f-a2af-4713-9c3d-80db59ef11a9.mxf) (error -13) Aborted (core dumped)

cth103 commented 1 year ago

That's strange - it's as if the update to the new version didn't work. Can you do

dcpomatic2 --version

wunderbarb commented 1 year ago

That's strange - it's as if the update to the new version didn't work. Can you do

dcpomatic2 --version

2.16.64devel 9342ee76eb

cth103 commented 1 year ago

It looks like for some reason the new .deb didn't install correctly - could you perhaps try again? The deb is here:

https://dcpomatic.com/temp/gh-21-open/f24e4f0/ubuntu-22.04-64/dcpomatic_2.16.64-f24e4f0-1_amd64.deb

When you do dcpomatic2 --version you should see f24e4f0 at the end.