intermittent getBlob exception

[kahing]

I haven't narrowed down what triggers this yet, but goofys CI tests trigger this (unclear which test):

java.util.NoSuchElementException: null
        at java.util.ArrayDeque.removeFirst(ArrayDeque.java:285)
        at com.google.common.io.Closer.close(Closer.java:212)
        at org.jclouds.util.Closeables2.closeQuietly(Closeables2.java:40)
        at org.jclouds.io.payloads.ByteSourcePayload.release(ByteSourcePayload.java:52)
        at org.jclouds.http.internal.PayloadEnclosingImpl.setPayload(PayloadEnclosingImpl.java:56)
        at org.jclouds.blobstore.domain.internal.BlobImpl.setPayload(BlobImpl.java:114)
        at org.jclouds.http.internal.PayloadEnclosingImpl.setPayload(PayloadEnclosingImpl.java:97)
        at org.jclouds.blobstore.config.LocalBlobStore.getBlob(LocalBlobStore.java:723)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at com.google.inject.internal.DelegatingInvocationHandler.invoke(DelegatingInvocationHandler.java:37)
        at com.sun.proxy.$Proxy40.getBlob(Unknown Source)
        at org.gaul.s3proxy.S3ProxyHandler.handleGetBlob(S3ProxyHandler.java:1640)
        at org.gaul.s3proxy.S3ProxyHandler.doHandle(S3ProxyHandler.java:673)
        at org.gaul.s3proxy.S3ProxyHandlerJetty.handle(S3ProxyHandlerJetty.java:70)
        at org.gaul.shaded.org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:97)
        at org.gaul.shaded.org.eclipse.jetty.server.Server.handle(Server.java:499)
        at org.gaul.shaded.org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:311)
        at org.gaul.shaded.org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:258)
        at org.gaul.shaded.org.eclipse.jetty.io.AbstractConnection$2.run(AbstractConnection.java:544)
        at org.gaul.shaded.org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:635)
        at org.gaul.shaded.org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:555)
        at java.lang.Thread.run(Thread.java:748)

[gaul]

This is an interesting stack trace! Closer raises an exception in removeFirst below:

    while (!stack.isEmpty()) {
      Closeable closeable = stack.removeFirst();

Closer.register protects against null elements so one would assume that this is impossible without concurrent modification. Yet only a single thread should ever handle this...

[kahing]

another one with a different backtrace:

[s3proxy] W 09-12 05:33:33.879 S3Proxy-Jetty-28 o.g.s.o.e.j.server.HttpChannel:396 |::] /goofys-test-a0gh6o5fe00nh9qu/testLargeFile
java.lang.IllegalStateException: STREAM
	at org.gaul.shaded.org.eclipse.jetty.server.Response.getWriter(Response.java:910)
	at org.gaul.s3proxy.S3ProxyHandler.sendSimpleErrorResponse(S3ProxyHandler.java:2864)
	at org.gaul.s3proxy.S3ProxyHandlerJetty.handle(S3ProxyHandlerJetty.java:146)
	at org.gaul.shaded.org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:97)
	at org.gaul.shaded.org.eclipse.jetty.server.Server.handle(Server.java:499)
	at org.gaul.shaded.org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:311)
	at org.gaul.shaded.org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:258)
	at org.gaul.shaded.org.eclipse.jetty.io.AbstractConnection$2.run(AbstractConnection.java:544)
	at org.gaul.shaded.org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:635)
	at org.gaul.shaded.org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:555)
	at java.base/java.lang.Thread.run(Thread.java:834)

This one causes the test to be stuck: https://travis-ci.org/kahing/goofys/jobs/583981057#L11071

[gaul]

Does this also happen in getBlob or another operation? The stack trace looks like one of the handlers called getWriter and while emitting some XML it throws an S3Exception. The handler closes the Writer and sendSimpleErrorResponse attempts to reopen it but fails. If you can reproduce this, adding a printStaceTrace will reveal the cause.

[gaul]

Actually the line

	at org.gaul.s3proxy.S3ProxyHandlerJetty.handle(S3ProxyHandlerJetty.java:146)

reveals the cause, a TimeoutException, likely from the client. In this case we need more robust handling, first figure out if the stream has be opened and conditionally call into sendSimpleErrorResponse.

[gaul]

It looks like sendSimpleErrorResponse should check ServletResponse.isCommitted:

https://docs.oracle.com/javaee/6/api/javax/servlet/ServletResponse.html#isCommitted()

[gaul]

Similar symptom seen in s3fs CI:

[s3proxy] W 07-09 12:54:28.324 S3Proxy-Jetty-95 o.g.s.o.e.j.server.HttpChannel:396 |::] /s3fs-integration-test/testrun-7332/big-file-s3fs.txt
java.lang.ArrayIndexOutOfBoundsException: -662657112
	at java.util.ArrayDeque.addFirst(ArrayDeque.java:227)
	at com.google.common.io.Closer.register(Closer.java:126)
	at org.jclouds.io.payloads.ByteSourcePayload.openStream(ByteSourcePayload.java:39)
	at org.jclouds.blobstore.config.LocalBlobStore.copyBlob(LocalBlobStore.java:759)
	at org.jclouds.blobstore.config.LocalBlobStore.getBlob(LocalBlobStore.java:677)
	at sun.reflect.GeneratedMethodAccessor17.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:606)
	at com.google.inject.internal.DelegatingInvocationHandler.invoke(DelegatingInvocationHandler.java:37)
	at com.sun.proxy.$Proxy40.getBlob(Unknown Source)
	at org.gaul.s3proxy.S3ProxyHandler.handleGetBlob(S3ProxyHandler.java:1712)
	at org.gaul.s3proxy.S3ProxyHandler.doHandle(S3ProxyHandler.java:684)
	at org.gaul.s3proxy.S3ProxyHandlerJetty.handle(S3ProxyHandlerJetty.java:76)
	at org.gaul.shaded.org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:97)
	at org.gaul.shaded.org.eclipse.jetty.server.Server.handle(Server.java:499)
	at org.gaul.shaded.org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:311)
	at org.gaul.shaded.org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:258)
	at org.gaul.shaded.org.eclipse.jetty.io.AbstractConnection$2.run(AbstractConnection.java:544)
	at org.gaul.shaded.org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:635)
	at org.gaul.shaded.org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:555)
	at java.lang.Thread.run(Thread.java:745)

[gaul]

Fixed in S3Proxy 1.8.0.

[gaul]

I still see this with S3Proxy 2.0.0:

java.lang.ArrayIndexOutOfBoundsException: Index 12 out of bounds for length 12
        at java.base/java.util.ArrayDeque.grow(ArrayDeque.java:158)
        at java.base/java.util.ArrayDeque.addFirst(ArrayDeque.java:290)
        at com.google.common.io.Closer.register(Closer.java:126)
        at org.jclouds.io.payloads.ByteSourcePayload.openStream(ByteSourcePayload.java:39)
        at org.jclouds.blobstore.config.LocalBlobStore.getBlob(LocalBlobStore.java:741)
        at org.jclouds.blobstore.config.LocalBlobStore.getBlob(LocalBlobStore.java:205)
        at org.jclouds.blobstore.config.LocalBlobStore.blobMetadata(LocalBlobStore.java:762)

[gaul]

Needs jclouds 2.6.0 upgrade.