Open kefo opened 4 years ago
Just to confirm: this error is appearing in the log at the moment you stop siege? What do you mean by "brings down Cantaloupe completely?"
This is an error that would be expected when a connection is closed while image data is being written to the response. It's a non-serious debug level error. I don't know how siege works, but my suspicion is that when you are stopping it, it's forcibly closing all of its connection(s) without waiting for any HTTP exchanges to complete.
this error is appearing in the log at the moment you stop siege?
Yes.
What do you mean by "brings down Cantaloupe completely?"
Cantaloupe dies. Its process is killed. It is no longer running.
but my suspicion is that when you are stopping it, it's forcibly closing all of its connection(s) without waiting for any HTTP exchanges to complete.
This is what I think is happening too, but I'm worried about whether something like this could happen, intentionally or unintentionally on the part of the client, when running in production.
I ran some tests using OpenJpeg instead of Kakadu. I get a pile of errors in the log when siege
stops, again suggesting it is forcibly closing the connections, but Cantaloupe does not go down. It remains up and I can restart a new test immediately. All-in-all, I performed 4-5 tests. Never once did Cantaloupe go down (though the errors appeared each time). So this seems, at least when it comes to JPEG2000 processors, specific to Kakadu.
One error stack from one of the OpenJpeg runs:
2020-10-10 08:18:10,335 INFO [qtp434176574-13] e.i.l.c.r.ErrorResource [AbstractResource.java:117] Handling GET /iiif/2/b9a5adbf-641b-3b89-20c8-f6556a9be1f0/full/900,900/0/default.jpg
2020-10-10 08:18:10,335 DEBUG [qtp434176574-13] e.i.l.c.r.ErrorResource [AbstractResource.java:120] Request headers: X-Forwarded-Path: /; Accept: */*; User-Agent: Mozilla/5.0 (pc-x86_64-linux-gnu) Siege/4.0.3rc4; X-Forwarded-Proto: HTTPS; X-Forwarded-Host: lakeimagesweb-staging.artic.edu; Connection: keep-alive; X-Forwarded-For: 198.40.24.68; Host: lakeimagesweb-staging.artic.edu; Accept-Encoding: gzip, deflate; X-Forwarded-Port: 443; X-Forwarded-Server: apache-server
2020-10-10 08:18:10,336 DEBUG [qtp434176574-13] e.i.l.c.r.ErrorResource [AbstractResource.java:568] Base URI assembled from X-Forwarded headers: https://lakeimagesweb-staging.artic.edu
2020-10-10 08:18:10,337 DEBUG [qtp434176574-13] e.i.l.c.r.HandlerServlet [HandlerServlet.java:175] Failed to acquire an error writer after failing to fully write the response. Most likely this was caused by the client closing the connection and is not a problem.
2020-10-10 08:18:10,337 DEBUG [qtp434176574-13] e.i.l.c.r.HandlerServlet [HandlerServlet.java:124] Responded to GET /iiif/2/b9a5adbf-641b-3b89-20c8-f6556a9be1f0/full/900,900/0/default.jpg with HTTP 500 in 3744 msec
2020-10-10 08:18:10,560 DEBUG [qtp434176574-74] e.i.l.c.p.Java2DUtil [Java2DUtil.java:1004] scale(): scaled 2013x3000 image to 900x900 using a BiCubic filter in 72 msec
2020-10-10 08:18:10,727 DEBUG [qtp434176574-74] e.i.l.c.p.Java2DUtil [Java2DUtil.java:1036] sharpen(): sharpened by 0.45 in 167 msec
2020-10-10 08:18:10,727 DEBUG [qtp434176574-74] e.i.l.c.p.c.JPEGImageWriter [AbstractIIOImageWriter.java:138] ImageIO plugin preferences: com.sun.imageio.plugins.jpeg.JPEGImageWriter
2020-10-10 08:18:10,728 DEBUG [qtp434176574-74] e.i.l.c.p.c.JPEGImageWriter [AbstractIIOImageWriter.java:51] Using com.sun.imageio.plugins.jpeg.JPEGImageWriter
2020-10-10 08:18:10,728 DEBUG [qtp434176574-74] e.i.l.c.p.c.JPEGImageWriter [JPEGImageWriter.java:115] Quality: 95; progressive: true
2020-10-10 08:18:10,817 DEBUG [work-nm-4263653] e.i.l.c.p.OpenJpegProcessor [OpenJpegProcessor.java:592] Deleting /usr/local/datagrinder/cantaloupe/tmp/OpenJpegProcessor-2c3d2b2f-6ed0-4f2e-8863-7739b7625ac7.bmp
2020-10-10 08:18:10,818 DEBUG [qtp434176574-74] e.i.l.c.p.OpenJpegProcessor [OpenJpegProcessor.java:479] process(): Closed (c1c1c2f5-5188-99bc-25ce-c348a56b933d_1:1_scale:900,900,bicubic_sharpen:0.45_encode:jpg_JPEG_95_interlace_#000000_8)
org.eclipse.jetty.io.EofException: Closed
at org.eclipse.jetty.server.HttpOutput.write(HttpOutput.java:575)
at javax.imageio.stream.MemoryCache.writeToStream(MemoryCache.java:172)
at javax.imageio.stream.MemoryCacheImageOutputStream.flushBefore(MemoryCacheImageOutputStream.java:192)
at javax.imageio.stream.ImageInputStreamImpl.flush(ImageInputStreamImpl.java:825)
at com.sun.imageio.plugins.jpeg.JPEGImageWriter.writeOnThread(JPEGImageWriter.java:1100)
at com.sun.imageio.plugins.jpeg.JPEGImageWriter.write(JPEGImageWriter.java:363)
at edu.illinois.library.cantaloupe.processor.codec.JPEGImageWriter.write(JPEGImageWriter.java:180)
at edu.illinois.library.cantaloupe.processor.codec.JPEGImageWriter.write(JPEGImageWriter.java:153)
at edu.illinois.library.cantaloupe.processor.Java2DPostProcessor.postProcess(Java2DPostProcessor.java:119)
at edu.illinois.library.cantaloupe.processor.OpenJpegProcessor.processInUnix(OpenJpegProcessor.java:574)
at edu.illinois.library.cantaloupe.processor.OpenJpegProcessor.process(OpenJpegProcessor.java:471)
at edu.illinois.library.cantaloupe.resource.ImageRepresentation.process(ImageRepresentation.java:180)
at edu.illinois.library.cantaloupe.resource.ImageRepresentation.copyOrProcess(ImageRepresentation.java:147)
at edu.illinois.library.cantaloupe.resource.ImageRepresentation.write(ImageRepresentation.java:127)
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:687)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
at org.eclipse.jetty.servlet.ServletHolder$NotAsyncServlet.service(ServletHolder.java:1391)
at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:760)
at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:547)
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:590)
at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235)
at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1607)
at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233)
at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1297)
at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188)
at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:485)
at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1577)
at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186)
at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1212)
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
at org.eclipse.jetty.server.Server.handle(Server.java:500)
at org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:383)
at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:547)
at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:375)
at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:270)
at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311)
at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103)
at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:117)
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:336)
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:313)
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171)
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:129)
at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:388)
at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:806)
at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:938)
at java.lang.Thread.run(Thread.java:748)
2020-10-10 08:18:10,818 INFO [qtp434176574-74] e.i.l.c.r.ErrorResource [AbstractResource.java:117] Handling GET /iiif/2/c1c1c2f5-5188-99bc-25ce-c348a56b933d/full/900,900/0/default.jpg
2020-10-10 08:18:10,818 DEBUG [qtp434176574-74] e.i.l.c.r.ErrorResource [AbstractResource.java:120] Request headers: X-Forwarded-Path: /; Accept: */*; User-Agent: Mozilla/5.0 (pc-x86_64-linux-gnu) Siege/4.0.3rc4; X-Forwarded-Proto: HTTPS; X-Forwarded-Host: lakeimagesweb-staging.artic.edu; Connection: keep-alive; X-Forwarded-For: 198.40.24.68; Host: lakeimagesweb-staging.artic.edu; Accept-Encoding: gzip, deflate; X-Forwarded-Port: 443; X-Forwarded-Server: apache-server
2020-10-10 08:18:10,818 DEBUG [qtp434176574-74] e.i.l.c.r.ErrorResource [AbstractResource.java:568] Base URI assembled from X-Forwarded headers: https://lakeimagesweb-staging.artic.edu
2020-10-10 08:18:10,819 DEBUG [qtp434176574-74] e.i.l.c.r.HandlerServlet [HandlerServlet.java:175] Failed to acquire an error writer after failing to fully write the response. Most likely this was caused by the client closing the connection and is not a problem.
2020-10-10 08:18:10,820 DEBUG [qtp434176574-74] e.i.l.c.r.HandlerServlet [HandlerServlet.java:124] Responded to GET /iiif/2/c1c1c2f5-5188-99bc-25ce-c348a56b933d/full/900,900/0/default.jpg with HTTP 500 in 2966 msec
Yes, it is probably specific to KakaduNativeProcessor.
I would like to try to reproduce this. Is it pretty straightforward to do with siege? I probably can't get to it today or maybe even this week, though.
Yes, I believe it is pretty straightforward with siege. I'm not doing anything too fancy. Here's the siege command:
siege -c 4 -t 2m -f data/10000_lakeimagesweb_staging.txt
That's 4 concurrent requests for 2 minutes using the URLs in the file. ( I suspect you could perform the test for a shorter period assuming we are correct in that it happens because siege is forcibly closing the connections.) I know I've run a siege test with a concurrency of '1' but I cannot recall whether I encountered this issue.
Hi @kefo ,
I wasn't able to reproduce the crash using that siege command. But I'm not sure what URLs I should be testing or whether it matters what image(s) I test with. Also, I don't have an Apache reverse proxy involved, but I don't know whether that matters.
This isn't fixed yet, but I'm going to close it as I'm now pretty sure it's a duplicate of #303.
Hello, @adolski . I think #303 was addressed in release 4.1.7. If so, this issue may need to be re-opened or a new issue created, let me know. (If #303 wasn't addressed in 4.1.7, then this can just function as a note for 4.1.7.)
I grabbed the 4.1.7 release and tested this out with kakadu. I get the same behavior from Cantaloupe (meaning that Cantaloupe dies after siege stops when using Kakadu) and more or less the same error:
2021-01-20 11:41:37,389 DEBUG [qtp434176574-43] e.i.l.c.c.FilesystemCache$ConcurrentFileOutputStream [FilesystemCache.java:183] close(): moving /data/local/datagrinder/cantaloupe/cache/image/9f/2c/59/b1/9f2c59b1e3391b1e73b278d3c00bd567_bda9ee8d24393755279b6bca92746ea7.jpg_qtp434176574-43.tmp to /data/local/datagrinder/cantaloupe/cache/image/9f/2c/59/b1/9f2c59b1e3391b1e73b278d3c00bd567_bda9ee8d24393755279b6bca92746ea7.jpg
2021-01-20 11:41:37,391 DEBUG [qtp434176574-15] e.i.l.c.p.c.JPEGImageWriter [JPEGImageWriter.java:115] Quality: 95; progressive: true
2021-01-20 11:41:37,393 DEBUG [qtp434176574-43] e.i.l.c.r.ImageRepresentation [ImageRepresentation.java:121] write(): null
java.io.IOException: null
at edu.illinois.library.cantaloupe.resource.ImageRepresentation.copyOrProcess(ImageRepresentation.java:149)
at edu.illinois.library.cantaloupe.resource.ImageRepresentation.write(ImageRepresentation.java:119)
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:687)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
at org.eclipse.jetty.servlet.ServletHolder$NotAsyncServlet.service(ServletHolder.java:1391)
at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:760)
at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:547)
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:590)
at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235)
at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1607)
at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233)
at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1297)
at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188)
at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:485)
at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1577)
at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186)
at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1212)
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
at org.eclipse.jetty.server.Server.handle(Server.java:500)
at org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:383)
at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:547)
at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:375)
at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:270)
at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311)
at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103)
at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:117)
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:336)
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:313)
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171)
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:129)
at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:388)
at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:806)
at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:938)
at java.lang.Thread.run(Thread.java:748)
Caused by: edu.illinois.library.cantaloupe.processor.ProcessorException: null
at edu.illinois.library.cantaloupe.processor.KakaduNativeProcessor.process(KakaduNativeProcessor.java:270)
at edu.illinois.library.cantaloupe.resource.ImageRepresentation.process(ImageRepresentation.java:180)
at edu.illinois.library.cantaloupe.resource.ImageRepresentation.copyOrProcess(ImageRepresentation.java:147)
... 39 common frames omitted
Caused by: org.eclipse.jetty.io.EofException: null
at org.eclipse.jetty.io.ChannelEndPoint.flush(ChannelEndPoint.java:283)
at org.eclipse.jetty.io.WriteFlusher.flush(WriteFlusher.java:422)
at org.eclipse.jetty.io.WriteFlusher.write(WriteFlusher.java:277)
at org.eclipse.jetty.io.AbstractEndPoint.write(AbstractEndPoint.java:381)
at org.eclipse.jetty.server.HttpConnection$SendCallback.process(HttpConnection.java:810)
at org.eclipse.jetty.util.IteratingCallback.processing(IteratingCallback.java:241)
at org.eclipse.jetty.util.IteratingCallback.iterate(IteratingCallback.java:223)
at org.eclipse.jetty.server.HttpConnection.send(HttpConnection.java:541)
at org.eclipse.jetty.server.HttpChannel.sendResponse(HttpChannel.java:829)
at org.eclipse.jetty.server.HttpChannel.write(HttpChannel.java:901)
at org.eclipse.jetty.server.HttpOutput.write(HttpOutput.java:259)
at org.eclipse.jetty.server.HttpOutput.write(HttpOutput.java:235)
at org.eclipse.jetty.server.HttpOutput.write(HttpOutput.java:608)
at org.apache.commons.io.output.ProxyOutputStream.write(ProxyOutputStream.java:90)
at org.apache.commons.io.output.TeeOutputStream.write(TeeOutputStream.java:64)
at javax.imageio.stream.MemoryCache.writeToStream(MemoryCache.java:172)
at javax.imageio.stream.MemoryCacheImageOutputStream.flushBefore(MemoryCacheImageOutputStream.java:192)
at javax.imageio.stream.ImageInputStreamImpl.flush(ImageInputStreamImpl.java:825)
at com.sun.imageio.plugins.jpeg.JPEGImageWriter.writeOnThread(JPEGImageWriter.java:1100)
at com.sun.imageio.plugins.jpeg.JPEGImageWriter.write(JPEGImageWriter.java:363)
at edu.illinois.library.cantaloupe.processor.codec.JPEGImageWriter.write(JPEGImageWriter.java:180)
at edu.illinois.library.cantaloupe.processor.codec.JPEGImageWriter.write(JPEGImageWriter.java:153)
at edu.illinois.library.cantaloupe.processor.KakaduNativeProcessor.postProcess(KakaduNativeProcessor.java:354)
at edu.illinois.library.cantaloupe.processor.KakaduNativeProcessor.process(KakaduNativeProcessor.java:267)
... 41 common frames omitted
Caused by: java.io.IOException: Connection reset by peer
at sun.nio.ch.FileDispatcherImpl.writev0(Native Method)
at sun.nio.ch.SocketDispatcher.writev(SocketDispatcher.java:51)
at sun.nio.ch.IOUtil.write(IOUtil.java:148)
at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:504)
at org.eclipse.jetty.io.ChannelEndPoint.flush(ChannelEndPoint.java:263)
... 64 common frames omitted
2021-01-20 11:41:37,393 DEBUG [qtp434176574-43] e.i.l.c.c.FilesystemCache [FilesystemCache.java:812] purge(OperationList): purging ddc57b70-e852-c1d5-c60f-c433e3fae794_1:1_scale:1100,,bicubic_sharpen:0.45_encode:jpg_JPEG_95_interlace_#000000_8...
2021-01-20 11:41:37,394 DEBUG [qtp434176574-43] e.i.l.c.p.c.JPEG2000KakaduImageReader [JPEG2000KakaduImageReader.java:630] Rendered region 0,0/550x821; source 0,0/1100x1640; 1x reduction factor; differential scale 9098428/10000000; PPI 1200.0x1200.0
11:41:37.394 [qtp434176574-43] ERROR e.i.l.c.p.c.JPEG2000KakaduImageReader -
2021-01-20 11:41:37,394 ERROR [qtp434176574-43] e.i.l.c.p.c.JPEG2000KakaduImageReader [JPEG2000KakaduImageReader.java:158]
The ERROR
items at the end are new.
I'm looking to upgrade to 4.1.6. I'm running tests against Cantaloupe using
siege
. Apache is in front of Cantaloupe as a proxy. All the requests are for not-tiled JPEG2000 images. We're using the kakadu processor.Interestingly, I can run tests, for example, that last 10 minutes and handle thousands and thousands of requests. Everything works well. But it seems that once the tests complete, the below happens, which brings down Cantaloupe completely. I can repeat this - and get the same result - with a test that runs for just 2 minutes.
Since thousands of requests succeed, and I can see this whether I run tests for 2 minutes or 10, my suspicion is that
siege
is closing the connection or ending the test in such a way thatsiege
is tripping up Cantaloupe and we get the below. I'd like to think that if we were to go to production that we would likely not hit this issue, but I'm not sure I want to take the risk.Is this a known issue and a vagary of
siege
? It feels like it shouldn't happen even so.(I don't know what happens when using openjpeg as the processor. I can run some tests if desirable.)
Thoughts?