intermittent getBlob exception

kahing commented 5 years ago

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 commented 5 years ago

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 commented 5 years ago

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 commented 5 years ago

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 commented 5 years ago

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 commented 5 years ago

It looks like sendSimpleErrorResponse should check ServletResponse.isCommitted:

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

gaul commented 4 years ago

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 commented 3 years ago

Fixed in S3Proxy 1.8.0.

gaul commented 2 years ago

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 commented 2 years ago

Needs jclouds 2.6.0 upgrade.

gaul / s3proxy

intermittent getBlob exception #303