search

cantaloupe-project / cantaloupe

High-performance dynamic image server in Java
https://cantaloupe-project.github.io/
Other
267 stars 107 forks source link

500 Errors with JP2s and OpenJpegProcessor #561

Open dannylamb opened 2 years ago

dannylamb commented 2 years ago

Some JP2s we are trying to serve with Cantaloupe are returning 500 errors. From the logs I can see it is using OpenJpeg and a bmp is being created from obj_decompress. But it fails with 500 suddenly at the end.

cantaloupe_1  | 2022-03-01T19:43:35.326093962Z 19:43:35.316 [http-nio-8080-exec-1] DEBUG e.i.l.c.i.Identifier - Raw path component: https%3A%2F%2Fislandora.traefik.me%2F_flysystem%2Ffedora%2F2022-03%2Fbad.jp2 -> decoded: https://islandora.traefik.me/_flysystem/fedora/2022-03/bad.jp2 -> scale constraint stripped: https://islandora.traefik.me/_flysystem/fedora/2022-03/bad.jp2 -> slashes substituted: https://islandora.traefik.me/_flysystem/fedora/2022-03/bad.jp2
cantaloupe_1  | 2022-03-01T19:43:35.327197116Z 19:43:35.326 [http-nio-8080-exec-1] INFO  e.i.l.c.r.i.v.ImageResource - Handling GET /cantaloupe/iiif/2/https%3A%2F%2Fislandora.traefik.me%2F_flysystem%2Ffedora%2F2022-03%2Fbad.jp2/full/774,/0/default.jpg
cantaloupe_1  | 2022-03-01T19:43:35.330105499Z 19:43:35.327 [http-nio-8080-exec-1] DEBUG e.i.l.c.r.i.v.ImageResource - Request headers: x-forwarded-for: 192.168.176.2; host: islandora.traefik.me; connection: close; user-agent: curl/7.68.0; accept: */*; authorization: Bearer XXX; x-forwarded-host: islandora.traefik.me; x-forwarded-port: 443; x-forwarded-proto: https; x-forwarded-server: db1a040c1828; x-real-ip: 192.168.176.1; accept-encoding: gzip
cantaloupe_1  | 2022-03-01T19:43:35.377095770Z 19:43:35.376 [http-nio-8080-exec-1] INFO  e.i.l.c.c.InfoCache - Max InfoCache capacity: 2438289 (10% max heap / 150-byte expected average info size)
cantaloupe_1  | 2022-03-01T19:43:35.463719679Z 19:43:35.461 [http-nio-8080-exec-1] DEBUG e.i.l.c.s.DelegateProxy - Instantiated delegate object in 80 msec
cantaloupe_1  | 2022-03-01T19:43:35.479293474Z 19:43:35.479 [http-nio-8080-exec-1] DEBUG e.i.l.c.c.CacheFactory - getSourceCache(): implementation changed; creating a new instance
cantaloupe_1  | 2022-03-01T19:43:35.573475920Z 19:43:35.570 [http-nio-8080-exec-1] DEBUG e.i.l.c.s.DelegateProxy - invokeUncached(): httpsource_resource_info() returned {"uri"=>"https://islandora.traefik.me/_flysystem/fedora/2022-03/bad.jp2", "headers"=>{"Authorization"=>"Bearer XXX"}} for args: (none) in 22 msec
cantaloupe_1  | 2022-03-01T19:43:35.625832330Z 19:43:35.625 [http-nio-8080-exec-1] INFO  o.e.j.util.log - Logging initialized @20839ms to org.eclipse.jetty.util.log.Slf4jLog
cantaloupe_1  | 2022-03-01T19:43:35.857221717Z 19:43:35.856 [http-nio-8080-exec-1] DEBUG e.i.l.c.s.HttpSource - Requesting HEAD https://islandora.traefik.me/_flysystem/fedora/2022-03/bad.jp2 (extra headers: Authorization: Bearer XXX)
cantaloupe_1  | 2022-03-01T19:43:35.978210984Z 19:43:35.977 [HttpClient@45682cd6-42] INFO  o.e.j.u.TypeUtil - JVM Runtime does not support Modules
cantaloupe_1  | 2022-03-01T19:43:36.512823863Z 19:43:36.512 [http-nio-8080-exec-1] INFO  e.i.l.c.p.OpenJpegProcessor - invoke(): opj_decompress
cantaloupe_1  | 2022-03-01T19:43:36.568229798Z 19:43:36.567 [http-nio-8080-exec-1] DEBUG e.i.l.c.p.ProcessorFactory - OpenJpegProcessor selected for format JP2 (ManualSelectionStrategy offered OpenJpegProcessor, ImageMagickProcessor)
cantaloupe_1  | 2022-03-01T19:43:36.569427141Z 19:43:36.569 [http-nio-8080-exec-1] DEBUG e.i.l.c.s.HttpSource - Resolved https://islandora.traefik.me/_flysystem/fedora/2022-03/bad.jp2 to https://islandora.traefik.me/_flysystem/fedora/2022-03/bad.jp2
cantaloupe_1  | 2022-03-01T19:43:36.571223011Z 19:43:36.571 [http-nio-8080-exec-1] DEBUG e.i.l.c.p.ProcessorConnector - Using DownloadStrategy to work around the incompatibility of HttpSource (a StreamSource) and OpenJpegProcessor (a FileProcessor)
cantaloupe_1  | 2022-03-01T19:43:36.766158570Z 19:43:36.765 [http-nio-8080-exec-1] DEBUG e.i.l.c.p.TempFileDownload - Downloading to /opt/tomcat/temp/ProcessorConnector-DownloadStrategy-d480c36c-475f-4d9a-b796-d7613f5e0587.jp2
cantaloupe_1  | 2022-03-01T19:43:37.173728113Z 19:43:37.173 [http-nio-8080-exec-1] DEBUG e.i.l.c.p.c.JPEG2000MetadataReader - Read in 2 msec: [size: 3096x4000] [tileSize: 3096x4000] [3 components] [16 bits/component] [5 DWT levels] [XMP? false]
cantaloupe_1  | 2022-03-01T19:43:37.341468476Z 19:43:37.341 [http-nio-8080-exec-1] DEBUG e.i.l.c.c.InfoService - readInfo(): read https://islandora.traefik.me/_flysystem/fedora/2022-03/bad.jp2 from OpenJpegProcessor in 173 msec
cantaloupe_1  | 2022-03-01T19:43:37.343110525Z 19:43:37.342 [work-nm-1205392] DEBUG e.i.l.c.c.InfoService - putInObjectCache(): adding info: https://islandora.traefik.me/_flysystem/fedora/2022-03/bad.jp2 (new size: 1)
cantaloupe_1  | 2022-03-01T19:43:37.343125771Z 19:43:37.343 [work-nm-1205392] DEBUG e.i.l.c.c.InfoCache - putInObjectCache(): adding info: https://islandora.traefik.me/_flysystem/fedora/2022-03/bad.jp2 (new size: 1)
cantaloupe_1  | 2022-03-01T19:43:37.353786583Z 19:43:37.353 [http-nio-8080-exec-1] DEBUG e.i.l.c.s.DelegateProxy - invokeUncached(): authorize() returned true for args: (none) in 1 msec
cantaloupe_1  | 2022-03-01T19:43:37.356919704Z 19:43:37.356 [http-nio-8080-exec-1] DEBUG e.i.l.c.r.i.v.ImageResource - Base URI assembled from X-Forwarded headers: https://islandora.traefik.me/cantaloupe
cantaloupe_1  | 2022-03-01T19:43:37.360147389Z 19:43:37.360 [http-nio-8080-exec-1] DEBUG e.i.l.c.r.ImageRepresentation - Derivative cache not available; writing directly to the response
cantaloupe_1  | 2022-03-01T19:43:37.360652852Z 19:43:37.360 [http-nio-8080-exec-1] DEBUG e.i.l.c.p.OpenJpegProcessor - Creating link from /opt/tomcat/temp/OpenJpegProcessor-af82b01e-e738-4407-85cd-3c85cd43d395.bmp to /dev/stdout
cantaloupe_1  | 2022-03-01T19:43:37.360933714Z 19:43:37.360 [http-nio-8080-exec-1] DEBUG e.i.l.c.p.OpenJpegProcessor - isQuietModeSupported(): invoking opj_decompress -h
cantaloupe_1  | 2022-03-01T19:43:37.410350895Z 19:43:37.410 [http-nio-8080-exec-1] INFO  e.i.l.c.p.OpenJpegProcessor - opj_decompress reports version 2.4.0
cantaloupe_1  | 2022-03-01T19:43:37.410492614Z 19:43:37.410 [http-nio-8080-exec-1] DEBUG e.i.l.c.p.OpenJpegProcessor - Invoking opj_decompress -quiet -i /opt/tomcat/temp/ProcessorConnector-DownloadStrategy-d480c36c-475f-4d9a-b796-d7613f5e0587.jp2 -r 2 -o /opt/tomcat/temp/OpenJpegProcessor-af82b01e-e738-4407-85cd-3c85cd43d395.bmp
cantaloupe_1  | 2022-03-01T19:43:37.465151107Z 19:43:37.464 [http-nio-8080-exec-1] DEBUG e.i.l.c.p.c.BMPImageReader - Using com.sun.imageio.plugins.bmp.BMPImageReader
cantaloupe_1  | 2022-03-01T19:43:37.465312515Z 19:43:37.465 [http-nio-8080-exec-1] DEBUG e.i.l.c.p.c.BMPImageReader - Ignoring metadata? true
cantaloupe_1  | 2022-03-01T19:43:37.607910478Z 19:43:37.607 [work-nm-1205392] DEBUG e.i.l.c.p.OpenJpegProcessor - Deleting /opt/tomcat/temp/OpenJpegProcessor-af82b01e-e738-4407-85cd-3c85cd43d395.bmp
cantaloupe_1  | 2022-03-01T19:43:37.609417160Z 19:43:37.609 [http-nio-8080-exec-1] INFO  e.i.l.c.r.ErrorResource - Handling GET /cantaloupe/iiif/2/https%3A%2F%2Fislandora.traefik.me%2F_flysystem%2Ffedora%2F2022-03%2Fbad.jp2/full/774,/0/default.jpg
cantaloupe_1  | 2022-03-01T19:43:37.609508582Z 19:43:37.609 [http-nio-8080-exec-1] DEBUG e.i.l.c.r.ErrorResource - Request headers: x-forwarded-for: 192.168.176.2; host: islandora.traefik.me; connection: close; user-agent: curl/7.68.0; accept: */*; authorization: Bearer XXX; x-forwarded-host: islandora.traefik.me; x-forwarded-port: 443; x-forwarded-proto: https; x-forwarded-server: db1a040c1828; x-real-ip: 192.168.176.1; accept-encoding: gzip
cantaloupe_1  | 2022-03-01T19:43:37.610502889Z 19:43:37.610 [http-nio-8080-exec-1] DEBUG e.i.l.c.r.ErrorResource - Base URI assembled from X-Forwarded headers: https://islandora.traefik.me/cantaloupe
cantaloupe_1  | 2022-03-01T19:43:37.682735002Z 192.168.176.2 - - [01/Mar/2022:19:43:37 +0000] "GET /cantaloupe/iiif/2/https%3A%2F%2Fislandora.traefik.me%2F_flysystem%2Ffedora%2F2022-03%2Fbad.jp2/full/774,/0/default.jpg HTTP/1.1" 500 3682 "-" "curl/7.68.0" "192.168.176.1"
cantaloupe_1  | 2022-03-01T19:43:37.684471080Z 19:43:37.684 [http-nio-8080-exec-1] DEBUG e.i.l.c.r.HandlerServlet - Responded to GET /iiif/2/https:/islandora.traefik.me/_flysystem/fedora/2022-03/bad.jp2/full/774,/0/default.jpg with HTTP 500 in 2457 msec

In the output of the response I'm getting this error.

danny@danny-XPS-13-7390:~/Code/bd/saic-dc-i8$ curl -H "Authorization: Bearer XXX" https://islandora.traefik.me/cantaloupe/iiif/2/https%3A%2F%2Fislandora.traefik.me%2F_flysystem%2Ffedora%2F2022-03%2Fbad.jp2/full/774,/0/default.jpg
500 Internal Server Error

New BMP version not implemented yet.

java.io.IOException: New BMP version not implemented yet.
    at edu.illinois.library.cantaloupe.resource.ImageRepresentation.copyOrProcess(ImageRepresentation.java:149)
    at edu.illinois.library.cantaloupe.resource.ImageRepresentation.write(ImageRepresentation.java:76)
    at edu.illinois.library.cantaloupe.resource.iiif.v2.ImageResource.doGET(ImageResource.java:213)
    at edu.illinois.library.cantaloupe.resource.HandlerServlet.handle(HandlerServlet.java:98)
    at edu.illinois.library.cantaloupe.resource.HandlerServlet.doGet(HandlerServlet.java:36)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:634)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:741)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
    at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:53)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
    at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:202)
    at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96)
    at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:541)
    at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:139)
    at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92)
    at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:690)
    at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:74)
    at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:343)
    at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:373)
    at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65)
    at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:868)
    at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1590)
    at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
    at java.lang.Thread.run(Thread.java:748)
Caused by: edu.illinois.library.cantaloupe.processor.ProcessorException: New BMP version not implemented yet.
    at edu.illinois.library.cantaloupe.processor.OpenJpegProcessor.process(OpenJpegProcessor.java:485)
    at edu.illinois.library.cantaloupe.resource.ImageRepresentation.process(ImageRepresentation.java:180)
    at edu.illinois.library.cantaloupe.resource.ImageRepresentation.copyOrProcess(ImageRepresentation.java:147)
    ... 28 more
Caused by: javax.imageio.IIOException: New BMP version not implemented yet.
    at com.sun.imageio.plugins.bmp.BMPImageReader.readHeader(BMPImageReader.java:504)
    at com.sun.imageio.plugins.bmp.BMPImageReader.read(BMPImageReader.java:744)
    at javax.imageio.ImageReader.read(ImageReader.java:939)
    at edu.illinois.library.cantaloupe.processor.codec.AbstractIIOImageReader.read(AbstractIIOImageReader.java:339)
    at edu.illinois.library.cantaloupe.processor.OpenJpegProcessor.processInUnix(OpenJpegProcessor.java:568)
    at edu.illinois.library.cantaloupe.processor.OpenJpegProcessor.process(OpenJpegProcessor.java:469)
    ... 30 more

I'm not sure why it would be trying to create a bmp behind the scenes if the OpenJpegProcessor does not support that format, so I thought I'd raise this issue. Here's my relevant ManualSelectionStrategy configuration.

processor.selection_strategy = ManualSelectionStrategy
processor.ManualSelectionStrategy.avi = FfmpegProcessor
processor.ManualSelectionStrategy.bmp = ImageMagickProcessor
processor.ManualSelectionStrategy.dcm = ImageMagickProcessor
processor.ManualSelectionStrategy.gif = ImageMagickProcessor
processor.ManualSelectionStrategy.jp2 = OpenJpegProcessor
processor.ManualSelectionStrategy.jpg = ImageMagickProcessor
processor.ManualSelectionStrategy.mov = FfmpegProcessor
processor.ManualSelectionStrategy.mp4 = FfmpegProcessor
processor.ManualSelectionStrategy.mpg = FfmpegProcessor                    
processor.ManualSelectionStrategy.pdf = ImageMagickProcessor
processor.ManualSelectionStrategy.png = ImageMagickProcessor               
processor.ManualSelectionStrategy.tif = ImageMagickProcessor
processor.ManualSelectionStrategy.webm = FfmpegProcessor
processor.ManualSelectionStrategy.webp = ImageMagickProcessor
processor.ManualSelectionStrategy.fallback = Java2dProcessor
adolski commented 2 years ago

Hi @dannylamb,

OpenJpegProcessor uses OpenJPEG's opj_decompress tool to decode JP2s. Because of the I/O limitations of this tool, they have to be decoded to intermediate BMPs first, and then those are read back in and converted to the target format.

The error is coming from the Java Image I/O BMP reader, which is not liking the BMPs that opj_decompress is emitting. I don't really know how to work around this.

OpenJpegProcessor is a Rube Goldberg machine and needs to be replaced with something that accesses the native OpenJPEG library. But this is a long way off.

cbutcosk commented 1 year ago

FWIW I encountered this recently, in our case the bug was rooted in 16-bit TIFF files had been compressed using opj_compress without downsampling to 8-bit. We fixed it by re-compressing the source image with proper downsampling source, though the JP2 file was quite old as well, so the newer version of OpenJPEG may also have helped?