New command using new tool is failing

[Joseph Anderson]

Hello,

I'm having a little trouble with running a new command. What I want to do is use openjpeg to convert my tif files to jpeg2000, but I keep running into some permissions error that I can't really figure out. I've added opj_compress (openjpeg's 'convert') as a new tool. Added a new command using that tool and then changed the tif rule to use that command. Here's the output that I'm getting though:

Standard output (stdout)
File found: 990bde50-e957-46d7-b413-411a3c59b625 %SIPDirectory%objects/US.NNFIT.SC.187.1.193A.tif

Checking for a manually normalized file by trying to get the unique file that matches SIP UUID 66d1d486-a810-424d-aa18-e9552ce88bf8 and whose currentlocation value starts with this path: %SIPDirectory%objects/manualNormalization/access/US.NNFIT.SC.187.1.193A.

No such file found.

File format: Image (Raster): Tagged Image File Format: TIFF (fmt/353)

Format Policy Rule: Format policy rule 71f3f537-5598-4757-a94c-76a0bac11f90

Format Policy Command Transcoding to jp2 with opj_compress

Command to execute: opj_compress -i /var/archivematica/sharedDirectory/currentlyProcessing/US.NNFIT.SC.187.1.193A-66d1d486-a810-424d-aa18-e9552ce88bf8/objects/US.NNFIT.SC.187.1.193A.tif -o /var/archivematica/sharedDirectory/currentlyProcessing/US.NNFIT.SC.187.1.193A-66d1d486-a810-424d-aa18-e9552ce88bf8/DIP/objects/990bde50-e957-46d7-b413-411a3c59b625-US.NNFIT.SC.187.1.193A.jp2 -n 6 -c [256,256],[256,256],[128,128] -t 512,512 -p RPCL -SOP -EPH -r 10

-----

Command stdout:

Config Error!-----

Command exit code: -1

access normalization failed, falling back to default access rule

Fallback Format Policy Rule: Format policy rule 50ec04f1-372d-435d-a7c6-a548e7006d74

Fallback Format Policy Command Copying file to access directory

Command to execute: cp -R "/var/archivematica/sharedDirectory/currentlyProcessing/US.NNFIT.SC.187.1.193A-66d1d486-a810-424d-aa18-e9552ce88bf8/objects/US.NNFIT.SC.187.1.193A.tif" "/var/archivematica/sharedDirectory/currentlyProcessing/US.NNFIT.SC.187.1.193A-66d1d486-a810-424d-aa18-e9552ce88bf8/DIP/objects/990bde50-e957-46d7-b413-411a3c59b625-US.NNFIT.SC.187.1.193A.tif"

-----

Command stdout:

-----

Command exit code: 0

Running verification command [COMMAND] Standard verification command (file exists only)

Executing: test -f "%outputLocation%"

Output location: None

-----

Command stdout:

Command to execute: test -f "/var/archivematica/sharedDirectory/currentlyProcessing/US.NNFIT.SC.187.1.193A-66d1d486-a810-424d-aa18-e9552ce88bf8/DIP/objects/990bde50-e957-46d7-b413-411a3c59b625-US.NNFIT.SC.187.1.193A.tif"

-----

Command stdout:

-----

Command exit code: 0

-----

Verification Command exit code: 0

Successfully normalized  US.NNFIT.SC.187.1.193A.tif for access

Errors and diagnostics (stderr)

[Errno 13] Permission deniedFailed: Transcoding to jp2 with opj_compress

Standard out: Config Error!

Standard error: [Errno 13] Permission denied

I'm able to use opj_compress directly on my server, and have successfully converted tifs to jp2, but for some reason it's getting blocked in the normalization here.

Any thoughts??

Best,

Joseph Anderson

[Ross Spencer]

Hi Joseph,

Working backwards I think can see the verification seems to pass on what looks to be a TIF in the DIP. 

In line eleven, there's a -1 exit status, however, and line 6 suggests a file wasn't found. A file not found error would align with a permission denied error later on, e.g. during a move. I believe. 

Does that help? Can you share the script at all? 

Best,

Ross

[Joseph Anderson]

Hi Ross,

Here's the command that I've entered in the command field:

opj_compress -i %fileFullName% -o %outputDirectory%%prefix%%fileName%%postfix%.jp2 -n 6 -c [256,256],[256,256],[128,128] -t 512,512 -p RPCL -SOP -EPH -r 10

Just to test after I got the error, I ran this from the terminal with sudo -u archivematica and it worked fine using files in the directories that Archivematica was trying to process in. I also tried running as my default user, and got a an error that I couldn't write to the archivematica shared directories. But I presume that archivematica is running the tools as the archivematica user...?

For another test, I just replaced the standard convert to jpg command in the command field to see if there were issue with how I added the new tool, but that worked fine. So I'm wondering if maybe there's an issue with running this particular command from the python virtual environment that archivematica uses. Is there a way I can test that out?

Thanks,

Joseph

[Ross Spencer]

Hi Joseph,

I wanted to give this a try, to see if it could push your work along. Unfortunately I'm not seeing any failure, but maybe my attempt could give you some pointers? That being said, everything you've written is exactly the right approach, so it's difficult to see where there are gaps. 

First, I grabbed the latest OpenJPEG from: https://github.com/uclouvain/openjpeg/releases/tag/v2.3.1

I extracted it (I'm running CentOS). And I copied the directory to /usr/share/ and then created a symlink to the three binaries in /usr/bin/ 

So, pretty standard stuff.

I didn't have any TIF I could convert, but I had a couple of PNG that I noticed would work. I tested them outside of the FPR and they worked with your command. I checked what Siegfried returned as a PUID (fmt/12) and set up the rule. 

Inside the FPR, the execution ran as expected:

File found: 435a6301-f02c-44aa-ad32-c44bfeb21e7f %SIPDirectory%objects/01.png

Checking for a manually normalized file by trying to get the unique file that matches SIP UUID f44006f2-cabb-4192-ae96-2b3af5e259a0 and whose currentlocation value starts with this path: %SIPDirectory%objects/manualNormalization/access/01.

No such file found.

File format: Image (Raster): Portable Network Graphics: PNG  (fmt/12)

Format Policy Rule: Format policy rule 0e2ae46e-e406-4c7d-9fb2-87fbc1662565

Format Policy Command Create JP2 from Source Images

Command to execute: opj_compress -i /var/archivematica/sharedDirectory/currentlyProcessing/p3-f44006f2-cabb-4192-ae96-2b3af5e259a0/objects/01.png -o /var/archivematica/sharedDirectory/currentlyProcessing/p3-f44006f2-cabb-4192-ae96-2b3af5e259a0/DIP/objects/435a6301-f02c-44aa-ad32-c44bfeb21e7f-01.jp2 -n 6 -c [256,256],[256,256],[128,128] -t 512,512 -p RPCL -SOP -EPH -r 10

-----

Command stdout:

[INFO] tile number 1 / 4

[INFO] tile number 2 / 4

[INFO] tile number 3 / 4

[INFO] tile number 4 / 4

[INFO] Generated outfile /var/archivematica/sharedDirectory/currentlyProcessing/p3-f44006f2-cabb-4192-ae96-2b3af5e259a0/DIP/objects/435a6301-f02c-44aa-ad32-c44bfeb21e7f-01.jp2

encode time: 302 ms 

-----

Command exit code: 0

Running verification command [COMMAND] Standard verification command (non zero filesize)

Executing: test -s "%outputLocation%"

Output location: None

-----

Command stdout:

Command to execute: test -s "/var/archivematica/sharedDirectory/currentlyProcessing/p3-f44006f2-cabb-4192-ae96-2b3af5e259a0/DIP/objects/435a6301-f02c-44aa-ad32-c44bfeb21e7f-01.jp2"

-----

Command stdout:

-----

Command exit code: 0

-----

Verification Command exit code: 0

Running event detail command [COMMAND] convert event detail

Executing: echo program=\"convert\"\; version=\"`convert -version | grep Version:`\"

Output location: None

Command to execute: echo program=\"convert\"\; version=\"`convert -version | grep Version:`\"

-----

Command stdout:

program="convert"; version="Version: ImageMagick 6.7.8-9 2019-08-08 Q16 http://www.imagemagick.org"

-----

Command exit code: 0

Successfully normalized  01.png for access

And in the FPR that looks as follows:

It's important to have the output location field complete, not just in the script command itself. But it doesn't look like the error that you're seeing. 

The "Config error!" string you see in your output looks like it comes from Archivematica: https://github.com/artefactual/archivematica/blob/stable/1.11.x/src/archivematicaCommon/lib/executeOrRunSubProcess.py#L129-L131 that's consistent with a permission error. You might be able to add more logging in that script to help. That might be a bit more involved than desired. 

Our two output strings (mine at the top):

Command to execute: opj_compress \

    -i /var/archivematica/sharedDirectory/currentlyProcessing/p3-f44006f2-cabb-4192-ae96-2b3af5e259a0/objects/03.png \

    -o /var/archivematica/sharedDirectory/currentlyProcessing/p3-f44006f2-cabb-4192-ae96-2b3af5e259a0/DIP/objects/d7020ccb-74cf-4e75-854f-f8532176b21c-03.jp2 \

    -n 6 -c [256,256],[256,256],[128,128] -t 512,512 -p RPCL -SOP -EPH -r 10

    

Command to execute: opj_compress \

    -i /var/archivematica/sharedDirectory/currentlyProcessing/US.NNFIT.SC.187.1.193A-66d1d486-a810-424d-aa18-e9552ce88bf8/objects/US.NNFIT.SC.187.1.193A.tif \

    -o /var/archivematica/sharedDirectory/currentlyProcessing/US.NNFIT.SC.187.1.193A-66d1d486-a810-424d-aa18-e9552ce88bf8/DIP/objects/990bde50-e957-46d7-b413-411a3c59b625-US.NNFIT.SC.187.1.193A.jp2 \

    -n 6 -c [256,256],[256,256],[128,128] -t 512,512 -p RPCL -SOP -EPH -r 10   

Look equivalent.

All I can think off right now:

* Is there a problem with path length?

* Is there another problem with the path? (it doesn't look ike it needs escaping at all)

* Is there a difference with the size of the input between my test PNG and your failing TIF? Is that causing the issue, e.g. is it taking too long to read? 

Again, you've done all the right things. Testing as the Archivematica user, outside of the FPR is a good approach. And we're using exactly the same commands. I might be missing something, but I'm at a bit of a loss to begin. Would you be able to try with other image types and see what happens? (My PNG files were just copies of https://github.com/artefactual/archivematica-sampledata/tree/master/TestTransfers/Evelyn's%20photos/objects using ImageMagick's convert. 

Maybe others have ideas or can see something here too?

Keep us updated, and if anything above triggers a useful line of investigation then that's good. 

Fingers-crossed for more luck with this. 

Ross

[Joseph Anderson]

Hi Ross,

Thanks for testing this out. It's good to see that it worked out for you. I will run through this again soon and report back. Thanks for the help!

[Ross Spencer]

It's nice to have another JPEG2000 command up our sleeve 😬 but yes! Looking forward to hearing more, and also 🤞🤞🤞.

Ross

[Joseph Anderson]

Hello again,

Ross,

Been playing around with this again. One thing I noticed is that you were running the tool as a bash script, whereas I was running it as command like (I selected this because this was how the convert command is used). Anyhow, this time I got a different error:

/tmp/42c46549-89b1-4048-acc0-cab60cd6a75b: line 2: opj_compress: command not found

Failed: Transcoding to jp2 with opj_compress

Standard out: 

Standard error: /tmp/42c46549-89b1-4048-acc0-cab60cd6a75b: line 2: opj_compress: command not found

Got me thinking, then. I'm running on redhat, and when I added openjpeg it installed into /usr/local/bin. I've tested running it as the archivematica user without any problem, but is it possible that when python runs a sys command that it doesn't have access to it because it's in /usr/local?? Not exactly well versed in this area.

Thanks,

Joseph

[Joseph Anderson]

Just to clarify, I got the new error when running as a bash script instead of a command line this time...

--

Joseph Anderson (he, him, his)

Digital Initiatives Librarian | Assistant Professor

Gladys Marcus Library | Goodman Resource Center

Fashion Institute of Technology

Seventh Avenue at 27th Street, Room E619

New York, New York  10001

www.fitnyc.edu/library

212.217.4359 phone | 212.217.4342 fax

FIT Campus is operating remotely for the foreseeable future. Please use email communications for the fastest response time. Connect with our services at fitnyc.edu/library.

[Joseph Anderson]

Hello Ross,

Looks like I figured out the issue. It seems that within my archivematica python virtual environment the path variable is somewhat different. So for instance when I run check 'env' as the archivematica user, I get:

PATH=/usr/local/bin:/usr/bin:/usr/local/sbin:/usr/sbin

And then when I run 'env' from within the python virtual environment, I get:

PATH=/sbin:/bin:/usr/sbin:/usr/bin

So, it wasn't actually a permissions issue—it just couldn't locate the opj_compress on the path from within the virtual environment. I'm not sure why exactly the path variable would be different (probably beyond my paygrade), but it was easy enough to modify the FPR command so that it includes the full path. And then it worked fine! Hooray!

Thanks for you help,

Joseph

[Ross Spencer]

Hi Joseph! Nice work on this. Good perseverance! I have had this tab open for a couple of days hoping inspiration would strike about what to check next. I have to say, I hadn't thought about debugging the path in the FPR like that, so that's a great debugging tip.

It sounds like you've a nice JPEG2000 workflow up and running. 

Many thanks for sharing your progress with us. 

All the best,

Ross